ArduCounter Support und neue Versionen (war: Stromzähler mit S0 Schnitt...)

[StefanStrobel]

Hallo Tobias,

die Long Counter existieren bisher nur auf der Fhem/Perl-Seite.
Im EEPROM / Flash speichere ich bisher nichts. Bei den Countern wäre das vermutlich auch ungesund.

Die Idee ist aber, dass die Pin-Konfiguration (aktive Pins, pullup, min length) im Flash gespeichert wird (wenn man das explizit mit einem set initiiert), so dass nach einem Cras / reboot sofort wieder richtig weiter gezählt werden kann. Das habe ich aber noch nicht implementiert.

Gruss
   Stefan

[tpm88]

Hallo Stefan,

ich habe folgende Verbindungsabbrüche (ESP8266 WLAN) im Log gesehen:

Code Auswählen Erweitern

2018-03-09_13:30:36 AC_Strom DISCONNECTED
2018-03-09_13:30:37 AC_Strom CONNECTED
2018-03-09_14:13:00 AC_Strom DISCONNECTED
2018-03-09_14:13:00 AC_Strom CONNECTED
2018-03-09_14:14:02 AC_Strom DISCONNECTED
2018-03-09_14:14:04 AC_Strom CONNECTED
2018-03-09_14:29:36 AC_Strom DISCONNECTED
2018-03-09_14:29:37 AC_Strom CONNECTED
2018-03-09_18:02:54 AC_Strom DISCONNECTED
2018-03-09_18:02:54 AC_Strom CONNECTED
2018-03-09_18:12:36 AC_Strom DISCONNECTED
2018-03-09_18:12:38 AC_Strom CONNECTED
2018-03-09_18:57:31 AC_Strom DISCONNECTED
2018-03-09_18:57:31 AC_Strom CONNECTED
2018-03-09_18:59:33 AC_Strom DISCONNECTED
2018-03-09_18:59:33 AC_Strom CONNECTED
2018-03-09_19:01:25 AC_Strom DISCONNECTED
2018-03-09_19:01:28 AC_Strom CONNECTED
2018-03-09_19:01:40 AC_Strom DISCONNECTED
2018-03-09_19:01:43 AC_Strom CONNECTED
2018-03-10_16:00:39 AC_Strom DISCONNECTED
2018-03-10_16:00:40 AC_Strom CONNECTED
2018-03-11_10:09:50 AC_Strom DISCONNECTED
2018-03-11_10:09:51 AC_Strom CONNECTED
2018-03-11_12:46:11 AC_Strom DISCONNECTED
2018-03-11_12:46:13 AC_Strom CONNECTED


In diesem Zeitraum habe ich definitiv nichts an meinem Setup geändert. Nun hat der wemos im Keller sicherlich nicht den besten WLAN-Empfang - aber als ich ihn an etwa gleicher Stelle noch mit ESPEasy in Betrieb hatte, waren die rssi Werte nicht so schlecht.

Gibt es da (im Sketch) irgendeine Debug-Möglichkeit?

Viele Grüße
Tobias

[StefanStrobel]

Hallo Tobias,

wenn Du das verbose-Attribut im ArduCounter-Gerät auf 5 setzt, dann schreibt das Modul sehr viele Details ins Fhem-Log. Unter anderem auch die Kommunikation mit dem Sketch.
Da sollte dann erkennbar sein, was genau passiert.
Probier das doch mal aus und poste dann einen größeren Ausschnitt aus dem Fhem-Log.

Gruss
    Stefan

[tpm88]

Hallo Stefan,

seit ich verbose auf 5 gesetzt habe, gab es wieder zwei kurze Unterbrechungen:

Code Auswählen Erweitern

2018-03-12_20:17:14 AC_Strom DISCONNECTED
2018-03-12_20:17:14 AC_Strom CONNECTED
2018-03-13_07:12:19 AC_Strom DISCONNECTED
2018-03-13_07:12:19 AC_Strom CONNECTED


1. Unterbrechung - Ausschnitt aus dem verbose 5 fhem log:

Code Auswählen Erweitern


...
2018.03.12 20:16:27 5: AC_Strom: Pin 5 debug: adding 1 to long count 4975 and interpolated count 4975
2018.03.12 20:16:27 4: AC_Strom: Pin 5 (pin5) Cnt 4314 lCnt 4976 iCnt 4976 (diff 1) in 11.162s, Rej 0, Avg 455ms, result 2.688
2018.03.12 20:16:27 5: AC_Strom: interval 20:16:16 until 20:16:27
2018.03.12 20:16:27 5: AC_Strom: set readings power5 to 2.688, timeDiff5 to 11162 and countDiff5 to 1
2018.03.12 20:16:27 5: AC_Strom: Device Time 382075.947, Drift 0.764s in 61108.776s, 0.00%
2018.03.12 20:16:32 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:16:32 5: AC_Strom: Write: k
2018.03.12 20:16:32 5: SW: k

2018.03.12 20:16:37 5: AC_Strom: Pin 5 debug: adding 1 to long count 4976 and interpolated count 4976
2018.03.12 20:16:37 4: AC_Strom: Pin 5 (pin5) Cnt 4315 lCnt 4977 iCnt 4977 (diff 1) in 11.153s, Rej 0, Avg 453ms, result 2.690
2018.03.12 20:16:37 5: AC_Strom: interval 20:16:26 until 20:16:37
2018.03.12 20:16:37 5: AC_Strom: set readings power5 to 2.690, timeDiff5 to 11153 and countDiff5 to 1
2018.03.12 20:16:37 5: AC_Strom: Device Time 382085.947, Drift 0.767s in 61118.779s, 0.00%
2018.03.12 20:16:42 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:16:42 5: AC_Strom: Write: k
2018.03.12 20:16:42 5: SW: k

2018.03.12 20:16:49 5: AC_Strom: Pin 5 debug: adding 1 to long count 4977 and interpolated count 4977
2018.03.12 20:16:49 4: AC_Strom: Pin 5 (pin5) Cnt 4316 lCnt 4978 iCnt 4978 (diff 1) in 11.132s, Rej 0, Avg 454ms, result 2.695
2018.03.12 20:16:49 5: AC_Strom: interval 20:16:38 until 20:16:49
2018.03.12 20:16:49 5: AC_Strom: set readings power5 to 2.695, timeDiff5 to 11132 and countDiff5 to 1
2018.03.12 20:16:49 5: AC_Strom: Device Time 382097.947, Drift 0.767s in 61130.779s, 0.00%
2018.03.12 20:16:52 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:16:52 5: AC_Strom: Write: k
2018.03.12 20:16:52 5: SW: k

2018.03.12 20:17:01 5: AC_Strom: Pin 5 debug: adding 1 to long count 4978 and interpolated count 4978
2018.03.12 20:17:01 4: AC_Strom: Pin 5 (pin5) Cnt 4317 lCnt 4979 iCnt 4979 (diff 1) in 11.178s, Rej 0, Avg 455ms, result 2.684
2018.03.12 20:17:01 5: AC_Strom: interval 20:16:50 until 20:17:01
2018.03.12 20:17:01 5: AC_Strom: set readings power5 to 2.684, timeDiff5 to 11178 and countDiff5 to 1
2018.03.12 20:17:01 5: AC_Strom: Device Time 382109.947, Drift 0.766s in 61142.778s, 0.00%
2018.03.12 20:17:02 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:17:02 5: AC_Strom: Write: k

2018.03.12 20:17:12 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:17:12 5: AC_Strom: Write: k
2018.03.12 20:17:12 5: SW: k

2018.03.12 20:17:14 3: AC_Strom: device didn't reply to k(eeepAlive). Is the right sketch flashed?
2018.03.12 20:17:14 1: 192.168.8.69:80 disconnected, waiting to reappear (AC_Strom)
2018.03.12 20:17:14 1: 192.168.8.69:80 reappeared (AC_Strom)
2018.03.12 20:17:14 3: AC_Strom: device maybe not initialized yet, set timer to send h(ello
2018.03.12 20:17:14 3: AC_Strom: unparseable message from device: R^M
2018.03.12 20:17:14 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.12 20:17:14 4: AC_Strom: device reported firmware 2.26
2018.03.12 20:17:14 3: AC_Strom: sending configuration from attributes to device
2018.03.12 20:17:14 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.12 20:17:14 5: AC_Strom: Write: 5,2,1,30a
2018.03.12 20:17:14 5: SW: 5,2,1,30a

2018.03.12 20:17:14 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.12 20:17:14 5: AC_Strom: Write: 2,300,1,1i
2018.03.12 20:17:14 5: SW: 2,300,1,1i

2018.03.12 20:17:14 4: AC_Strom: device sent time: T 382123077 boot at 561^M
2018.03.12 20:17:14 3: AC_Strom: unparseable message from device: P5 falling pullup min 30^M
2018.03.12 20:17:14 3: AC_Strom: device: defined P5 falling pullup min 30^M
2018.03.12 20:17:14 3: AC_Strom: device: intervals set to 2 300 1 1^M
2018.03.12 20:17:23 5: AC_Strom: Pin 5 debug: adding 1 to long count 4979 and interpolated count 4979
2018.03.12 20:17:23 4: AC_Strom: Pin 5 (pin5) Cnt 4319 lCnt 4980 iCnt 4980 (diff 1) in 11.218s, Rej 0, Avg 457ms, result 2.674
2018.03.12 20:17:23 5: AC_Strom: interval 20:17:12 until 20:17:23
2018.03.12 20:17:23 5: AC_Strom: set readings power5 to 2.674, timeDiff5 to 11218 and countDiff5 to 1
2018.03.12 20:17:23 5: AC_Strom: Device Time 382131.947, Drift 0.772s in 61164.784s, 0.00%
2018.03.12 20:17:24 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:17:24 5: AC_Strom: Write: k
2018.03.12 20:17:24 5: SW: k

2018.03.12 20:17:33 5: AC_Strom: Pin 5 debug: adding 1 to long count 4980 and interpolated count 4980
2018.03.12 20:17:33 4: AC_Strom: Pin 5 (pin5) Cnt 4320 lCnt 4981 iCnt 4981 (diff 1) in 11.245s, Rej 0, Avg 454ms, result 2.668
2018.03.12 20:17:33 5: AC_Strom: interval 20:17:22 until 20:17:33
2018.03.12 20:17:33 5: AC_Strom: set readings power5 to 2.668, timeDiff5 to 11245 and countDiff5 to 1
2018.03.12 20:17:33 5: AC_Strom: Device Time 382141.947, Drift 0.767s in 61174.779s, 0.00%
2018.03.12 20:17:34 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:17:34 5: AC_Strom: Write: k
2018.03.12 20:17:34 5: SW: k

2018.03.12 20:17:44 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:17:44 5: AC_Strom: Write: k
2018.03.12 20:17:44 5: SW: k

2018.03.12 20:17:45 5: AC_Strom: Pin 5 debug: adding 1 to long count 4981 and interpolated count 4981
2018.03.12 20:17:45 4: AC_Strom: Pin 5 (pin5) Cnt 4321 lCnt 4982 iCnt 4982 (diff 1) in 11.185s, Rej 0, Avg 454ms, result 2.682
2018.03.12 20:17:45 5: AC_Strom: interval 20:17:34 until 20:17:45
2018.03.12 20:17:45 5: AC_Strom: set readings power5 to 2.682, timeDiff5 to 11185 and countDiff5 to 1
2018.03.12 20:17:45 5: AC_Strom: Device Time 382153.947, Drift 0.765s in 61186.777s, 0.00%
2018.03.12 20:17:54 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:17:54 5: AC_Strom: Write: k
2018.03.12 20:17:54 5: SW: k

2018.03.12 20:17:57 5: AC_Strom: Pin 5 debug: adding 1 to long count 4982 and interpolated count 4982
2018.03.12 20:17:57 4: AC_Strom: Pin 5 (pin5) Cnt 4322 lCnt 4983 iCnt 4983 (diff 1) in 11.196s, Rej 0, Avg 456ms, result 2.679
2018.03.12 20:17:57 5: AC_Strom: interval 20:17:46 until 20:17:57
2018.03.12 20:17:57 5: AC_Strom: set readings power5 to 2.679, timeDiff5 to 11196 and countDiff5 to 1
2018.03.12 20:17:57 5: AC_Strom: Device Time 382165.947, Drift 0.766s in 61198.778s, 0.00%
2018.03.12 20:18:04 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:18:04 5: AC_Strom: Write: k
2018.03.12 20:18:04 5: SW: k

2018.03.12 20:18:07 5: AC_Strom: Pin 5 debug: adding 1 to long count 4983 and interpolated count 4983
2018.03.12 20:18:07 4: AC_Strom: Pin 5 (pin5) Cnt 4323 lCnt 4984 iCnt 4984 (diff 1) in 11.200s, Rej 0, Avg 454ms, result 2.678
2018.03.12 20:18:07 5: AC_Strom: interval 20:17:56 until 20:18:07
2018.03.12 20:18:07 5: AC_Strom: set readings power5 to 2.678, timeDiff5 to 11200 and countDiff5 to 1
2018.03.12 20:18:07 5: AC_Strom: Device Time 382175.947, Drift 0.765s in 61208.777s, 0.00%
2018.03.12 20:18:14 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:18:14 5: AC_Strom: Write: k
2018.03.12 20:18:14 5: SW: k

2018.03.12 20:18:19 5: AC_Strom: Pin 5 debug: adding 1 to long count 4984 and interpolated count 4984
2018.03.12 20:18:19 4: AC_Strom: Pin 5 (pin5) Cnt 4324 lCnt 4985 iCnt 4985 (diff 1) in 11.193s, Rej 0, Avg 458ms, result 2.680
2018.03.12 20:18:19 5: AC_Strom: interval 20:18:08 until 20:18:19
2018.03.12 20:18:19 5: AC_Strom: set readings power5 to 2.680, timeDiff5 to 11193 and countDiff5 to 1
2018.03.12 20:18:19 5: AC_Strom: Device Time 382187.947, Drift 0.767s in 61220.779s, 0.00%
2018.03.12 20:18:24 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:18:24 5: AC_Strom: Write: k
2018.03.12 20:18:24 5: SW: k

2018.03.12 20:18:29 5: AC_Strom: Pin 5 debug: adding 1 to long count 4985 and interpolated count 4985
2018.03.12 20:18:29 4: AC_Strom: Pin 5 (pin5) Cnt 4325 lCnt 4986 iCnt 4986 (diff 1) in 11.227s, Rej 0, Avg 457ms, result 2.672
2018.03.12 20:18:29 5: AC_Strom: interval 20:18:18 until 20:18:29
2018.03.12 20:18:29 5: AC_Strom: set readings power5 to 2.672, timeDiff5 to 11227 and countDiff5 to 1
2018.03.12 20:18:29 5: AC_Strom: Device Time 382197.947, Drift 0.766s in 61230.778s, 0.00%
2018.03.12 20:18:34 5: AC_Strom: sending k(eepAlive) to device
2018.03.12 20:18:34 5: AC_Strom: Write: k
2018.03.12 20:18:34 5: SW: k
...


2. Unterbrechung - Ausschnitt aus dem verbose 5 fhem log:

Code Auswählen Erweitern


...
2018.03.13 07:10:47 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:10:47 5: AC_Strom: Write: k
2018.03.13 07:10:47 5: SW: k

2018.03.13 07:10:57 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:10:57 5: AC_Strom: Write: k
2018.03.13 07:10:57 5: SW: k

2018.03.13 07:11:07 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:11:07 5: AC_Strom: Write: k
2018.03.13 07:11:07 5: SW: k

2018.03.13 07:11:17 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:11:17 5: AC_Strom: Write: k
2018.03.13 07:11:17 5: SW: k

2018.03.13 07:11:27 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:11:27 5: AC_Strom: Write: k
2018.03.13 07:11:27 5: SW: k

2018.03.13 07:11:37 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:11:37 5: AC_Strom: Write: k
2018.03.13 07:11:37 5: SW: k

2018.03.13 07:11:46 5: AC_Strom: Pin 5 debug: adding 1 to long count 5370 and interpolated count 5370
2018.03.13 07:11:46 4: AC_Strom: Pin 5 (pin5) Cnt 4711 lCnt 5371 iCnt 5371 (diff 1) in 83.901s, Rej 0, Avg 768ms, result 0.358
2018.03.13 07:11:46 5: AC_Strom: interval 07:10:22 until 07:11:46
2018.03.13 07:11:46 5: AC_Strom: set readings power5 to 0.358, timeDiff5 to 83901 and countDiff5 to 1
2018.03.13 07:11:46 5: AC_Strom: Device Time 421393.948, Drift 0.177s in 13974.177s, 0.00%
2018.03.13 07:11:47 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:11:47 5: AC_Strom: Write: k
2018.03.13 07:11:47 5: SW: k

2018.03.13 07:11:57 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:11:57 5: AC_Strom: Write: k
2018.03.13 07:11:57 5: SW: k

2018.03.13 07:12:07 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:12:07 5: AC_Strom: Write: k
2018.03.13 07:12:07 5: SW: k

2018.03.13 07:12:17 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:12:17 5: AC_Strom: Write: k
2018.03.13 07:12:17 5: SW: k

2018.03.13 07:12:19 3: AC_Strom: device didn't reply to k(eeepAlive). Is the right sketch flashed?
2018.03.13 07:12:19 1: 192.168.8.69:80 disconnected, waiting to reappear (AC_Strom)
2018.03.13 07:12:19 1: 192.168.8.69:80 reappeared (AC_Strom)
2018.03.13 07:12:19 3: AC_Strom: device maybe not initialized yet, set timer to send h(ello
2018.03.13 07:12:19 3: AC_Strom: unparseable message from device: a^M
2018.03.13 07:12:19 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.13 07:12:19 4: AC_Strom: device reported firmware 2.26
2018.03.13 07:12:19 3: AC_Strom: sending configuration from attributes to device
2018.03.13 07:12:19 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.13 07:12:19 5: AC_Strom: Write: 5,2,1,30a
2018.03.13 07:12:19 5: SW: 5,2,1,30a

2018.03.13 07:12:19 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.13 07:12:19 5: AC_Strom: Write: 2,300,1,1i
2018.03.13 07:12:19 5: SW: 2,300,1,1i

2018.03.13 07:12:19 4: AC_Strom: device sent time: T 421427741 boot at 561^M
2018.03.13 07:12:19 3: AC_Strom: unparseable message from device: P5 falling pullup min 30^M
2018.03.13 07:12:19 3: AC_Strom: device: defined P5 falling pullup min 30^M
2018.03.13 07:12:19 3: AC_Strom: device: intervals set to 2 300 1 1^M
2018.03.13 07:12:29 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:12:29 5: AC_Strom: Write: k
2018.03.13 07:12:29 5: SW: k

2018.03.13 07:12:39 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:12:39 5: AC_Strom: Write: k
2018.03.13 07:12:39 5: SW: k

2018.03.13 07:12:48 5: AC_Strom: Pin 5 debug: adding 1 to long count 5371 and interpolated count 5371
2018.03.13 07:12:48 4: AC_Strom: Pin 5 (pin5) Cnt 4713 lCnt 5372 iCnt 5372 (diff 1) in 30.713s, Rej 1, Avg 1284ms, result 0.977
2018.03.13 07:12:48 5: AC_Strom: interval 07:12:17 until 07:12:48
2018.03.13 07:12:48 5: AC_Strom: set readings power5 to 0.977, timeDiff5 to 30713 and countDiff5 to 1
2018.03.13 07:12:48 5: AC_Strom: Device Time 421455.948, Drift 0.177s in 14036.177s, 0.00%
2018.03.13 07:12:49 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:12:49 5: AC_Strom: Write: k
2018.03.13 07:12:49 5: SW: k

2018.03.13 07:12:59 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:12:59 5: AC_Strom: Write: k
2018.03.13 07:12:59 5: SW: k

2018.03.13 07:13:09 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:13:09 5: AC_Strom: Write: k
2018.03.13 07:13:09 5: SW: k

2018.03.13 07:13:19 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 07:13:19 5: AC_Strom: Write: k
2018.03.13 07:13:19 5: SW: k

2018.03.13 07:13:20 5: AC_Strom: Pin 5 debug: adding 1 to long count 5372 and interpolated count 5372
2018.03.13 07:13:20 4: AC_Strom: Pin 5 (pin5) Cnt 4714 lCnt 5373 iCnt 5373 (diff 1) in 31.378s, Rej 1, Avg 1282ms, result 0.956
2018.03.13 07:13:20 5: AC_Strom: interval 07:12:48 until 07:13:20
2018.03.13 07:13:20 5: AC_Strom: set readings power5 to 0.956, timeDiff5 to 31378 and countDiff5 to 1
2018.03.13 07:13:20 5: AC_Strom: Device Time 421487.948, Drift 0.176s in 14068.176s, 0.00%
2018.03.13 07:13:29 5: AC_Strom: sending k(eepAlive) to device
...


Kannst Du aus den Logs eine Ursache herauslesen?

VG
Tobias

[StefanStrobel]

Hallo Tobias,

Das Modul sendet alle 10 Sekunden ein ,,k" an den ESP und erwartet eine ,,alive"-Antwort. Wenn die nicht innerhalb von 2 Sekunden kommt, dann schließt das Modul die TCP-Verbindung und versucht sie neu aufzubauen.
Ohne so einen Mechanismus kann es passieren, dass ein Crash des ESP erst viel später bemerkt wird und dazwischen Impulse nicht gezählt werden.
Bei Deinen Abbrüchen hat aber der ESP gar nicht neu gestartet und ist folglich auch nicht abgestürzt. Nur die alive-Antwort kam nicht rechtzeitig.
Um die genaue Ursache dafür zu finden muss ich vermutlich noch ein paar Debug-Ausgaben einbauen. Ich hoffe dass ich am Wochenende dazu komme und dann poste ich eine neue Version.

Gruß und vielen Dank fürs Testen
    Stefan

[tpm88]

Hallo Stefan,

hier ist noch etwas, was vielleicht noch nicht optimal funktioniert. Beim Restart von FHEM läuft die Initialisierung des AC offenbar immer zweimal ab. Das konnte ich reproduzieren.

Anbei ein verbose 5 Log vom FHEM-Start - zur besseren Übersicht habe ich alle Nicht-AC Zeilen ausgelassen:

Code Auswählen Erweitern


...
2018.03.13 18:42:49 5: AC_Strom: Notify called with events: INITIALIZED, open device and set timer to send hello to device
2018.03.13 18:42:49 5: AC_Strom: ArduCounter_Open trying to open connection
2018.03.13 18:42:49 3: Opening AC_Strom device 192.168.8.69:80
2018.03.13 18:42:49 3: AC_Strom device opened
2018.03.13 18:42:49 5: AC_Strom: ArduCounter_Open succeeded - set timer to send hello
...
2018.03.13 18:42:55 0: Featurelevel: 5.8
2018.03.13 18:42:55 0: Server started with 207 defined entities (fhem.pl:16354/2018-03-09 perl:5.020002 os:linux user:fhem pid:26102)
2018.03.13 18:42:55 3: AC_Strom: sending h(ello) to device to ask for version
2018.03.13 18:42:55 5: AC_Strom: Write: h
2018.03.13 18:42:55 5: SW: h

2018.03.13 18:42:55 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.13 18:42:55 4: AC_Strom: device reported firmware 2.26
2018.03.13 18:42:55 3: AC_Strom: sending configuration from attributes to device
2018.03.13 18:42:55 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.13 18:42:55 1: PERL WARNING: Use of uninitialized value in split at ./FHEM/98_ArduCounter.pm line 375.
2018.03.13 18:42:55 5: AC_Strom: Write: 5,2,1,30a
2018.03.13 18:42:55 5: SW: 5,2,1,30a

2018.03.13 18:42:55 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.13 18:42:55 5: AC_Strom: Write: 2,300,1,1i
2018.03.13 18:42:55 5: SW: 2,300,1,1i

2018.03.13 18:42:55 4: AC_Strom: device sent time: T 462856493 boot at 561
2018.03.13 18:42:55 3: AC_Strom: unparseable message from device: P5 falling pullup min 30
2018.03.13 18:42:55 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.13 18:42:55 4: AC_Strom: device reported firmware 2.26
2018.03.13 18:42:55 3: AC_Strom: sending configuration from attributes to device
2018.03.13 18:42:55 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.13 18:42:55 5: AC_Strom: Write: 5,2,1,30a
2018.03.13 18:42:55 5: SW: 5,2,1,30a

2018.03.13 18:42:55 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.13 18:42:55 5: AC_Strom: Write: 2,300,1,1i
2018.03.13 18:42:55 5: SW: 2,300,1,1i

2018.03.13 18:42:55 4: AC_Strom: device sent time: T 462863039 boot at 561
2018.03.13 18:42:55 3: AC_Strom: unparseable message from device: P5 falling pullup min 30
2018.03.13 18:42:56 3: AC_Strom: device: defined P5 falling pullup min 30
2018.03.13 18:42:56 3: AC_Strom: device: intervals set to 2 300 1 1
2018.03.13 18:42:56 3: AC_Strom: device: defined P5 falling pullup min 30
2018.03.13 18:42:56 3: AC_Strom: device: intervals set to 2 300 1 1
...
2018.03.13 18:42:59 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 18:42:59 5: AC_Strom: Write: k
2018.03.13 18:42:59 5: SW: k

2018.03.13 18:43:09 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 18:43:09 5: AC_Strom: Write: k
2018.03.13 18:43:09 5: SW: k

2018.03.13 18:43:19 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 18:43:19 5: AC_Strom: Write: k
2018.03.13 18:43:19 5: SW: k

2018.03.13 18:43:24 5: AC_Strom: Pin 5 debug: adding 1 to long count 5879 and interpolated count 5879
2018.03.13 18:43:24 4: AC_Strom: Pin 5 (pin5) Cnt 5221 lCnt 5880 iCnt 5880 (diff 1) in 112.310s, Rej 0, Avg 4624ms, result 0.267
2018.03.13 18:43:24 5: AC_Strom: interval 18:41:32 until 18:43:24
2018.03.13 18:43:24 5: AC_Strom: set readings power5 to 0.267, timeDiff5 to 112310 and countDiff5 to 1
2018.03.13 18:43:24 5: AC_Strom: Initialize clock offset to 1520500112.61918
2018.03.13 18:43:24 5: AC_Strom: Device Time 462891.949, Drift 0.000s in 0.000s

2018.03.13 18:43:29 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 18:43:29 5: AC_Strom: Write: k
2018.03.13 18:43:29 5: SW: k

2018.03.13 18:43:39 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 18:43:39 5: AC_Strom: Write: k
2018.03.13 18:43:39 5: SW: k

2018.03.13 18:43:49 5: AC_Strom: sending k(eepAlive) to device
2018.03.13 18:43:49 5: AC_Strom: Write: k
2018.03.13 18:43:49 5: SW: k


VG
Tobias

[tpm88]

Bei Deinen Abbrüchen hat aber der ESP gar nicht neu gestartet und ist folglich auch nicht abgestürzt. Nur die alive-Antwort kam nicht rechtzeitig.
Um die genaue Ursache dafür zu finden muss ich vermutlich noch ein paar Debug-Ausgaben einbauen.

Hallo Stefan.

Ich habe den freezemon eingerichtet, um festzustellen, ob ich zeitgleich mit den Verbindungsabbrüchen freezes im FHEM sehe. Das ist aber definitiv nicht der Fall. Letzter aufgezeichneter freeze war vom FHEM restart nach dem Backup nachts.

Code Auswählen Erweitern

fhem> list fm

Internals:
   NAME       fm
   NR         207
   NTFY_ORDER 99-fm
   STATE      s:03:18:38 e:03:18:40 f:2.546 d:DENON_AVR_ConnectionCheck(myDenon) SIP_watch_listen(N/A)
   TYPE       freezemon
   VERSION    0.0.18
   READINGS:
     2018-03-16 03:18:40   fcDay           1
     2018-03-16 00:00:57   fcDayLast       4
     2018-03-16 03:18:40   freezeDevice    DENON_AVR_ConnectionCheck(myDenon) SIP_watch_listen(N/A)
     2018-03-16 03:18:40   freezeTime      2.546
     2018-03-16 03:18:40   ftDay           2.546
     2018-03-16 00:00:57   ftDayLast       7.779
     2018-03-16 03:18:40   state           s:03:18:38 e:03:18:40 f:2.546 d:DENON_AVR_ConnectionCheck(myDenon) SIP_watch_listen(N/A)


Möglicherweise verliert der wemos kurzzeitig die WLAN Verbindung zur FritzBox. Hierzu werde ich mal das Logging für WLAN Anmeldungen in der FritzBox aktivieren.

Vorher gab es vier Abbrüche kurz hintereinander - hierzu nochmal das ungekürzte fhem verbose 5 Log für den Zeitraum:

Code Auswählen Erweitern

2018.03.16 10:33:08 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:33:08 5: AC_Strom: Write: k
2018.03.16 10:33:08 5: SW: k

2018.03.16 10:33:18 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:33:18 5: AC_Strom: Write: k
2018.03.16 10:33:18 5: SW: k

2018.03.16 10:33:28 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:33:28 5: AC_Strom: Write: k
2018.03.16 10:33:28 5: SW: k

2018.03.16 10:33:30 3: AC_Strom: device didn't reply to k(eeepAlive). Is the right sketch flashed?
2018.03.16 10:33:30 1: 192.168.8.69:80 disconnected, waiting to reappear (AC_Strom)
2018.03.16 10:33:30 1: 192.168.8.69:80 reappeared (AC_Strom)
2018.03.16 10:33:30 3: AC_Strom: device maybe not initialized yet, set timer to send h(ello
2018.03.16 10:33:33 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.16 10:33:33 4: AC_Strom: device reported firmware 2.26
2018.03.16 10:33:33 3: AC_Strom: sending configuration from attributes to device
2018.03.16 10:33:33 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.16 10:33:33 5: AC_Strom: Write: 5,2,1,30a
2018.03.16 10:33:33 5: SW: 5,2,1,30a

2018.03.16 10:33:33 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.16 10:33:33 5: AC_Strom: Write: 2,300,1,1i
2018.03.16 10:33:33 5: SW: 2,300,1,1i

2018.03.16 10:33:33 4: AC_Strom: device sent time: T 74773060 boot at 560^M
2018.03.16 10:33:33 3: AC_Strom: unparseable message from device: P5 falling pullup min 30^M
2018.03.16 10:33:33 5: AC_Strom: Pin 5 debug: adding 1 to long count 6726 and interpolated count 6726
2018.03.16 10:33:33 4: AC_Strom: Pin 5 (pin5) Cnt 696 lCnt 6727 iCnt 6727 (diff 1) in 143.070s, Rej 0, Avg 4810ms, result 0.210
2018.03.16 10:33:33 5: AC_Strom: interval 10:31:10 until 10:33:33
2018.03.16 10:33:33 5: AC_Strom: set readings power5 to 0.210, timeDiff5 to 143070 and countDiff5 to 1
2018.03.16 10:33:33 5: AC_Strom: Device Time 74774.566, Drift 1.407s in 26031.407s, 0.01%
2018.03.16 10:33:37 3: AC_Strom: device: defined P5 falling pullup min 30^M
2018.03.16 10:33:38 3: AC_Strom: device: intervals set to 2 300 1 1^M
2018.03.16 10:33:40 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:33:40 5: AC_Strom: Write: k
2018.03.16 10:33:40 5: SW: k

2018.03.16 10:33:50 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:33:50 5: AC_Strom: Write: k
2018.03.16 10:33:50 5: SW: k

2018.03.16 10:34:00 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:34:00 5: AC_Strom: Write: k
2018.03.16 10:34:00 5: SW: k

2018.03.16 10:34:02 3: AC_Strom: device didn't reply to k(eeepAlive). Is the right sketch flashed?
2018.03.16 10:34:02 1: 192.168.8.69:80 disconnected, waiting to reappear (AC_Strom)
2018.03.16 10:34:02 1: 192.168.8.69:80 reappeared (AC_Strom)
2018.03.16 10:34:02 3: AC_Strom: device maybe not initialized yet, set timer to send h(ello
2018.03.16 10:34:02 3: AC_Strom: unparseable message from device: a^M
2018.03.16 10:34:02 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.16 10:34:02 4: AC_Strom: device reported firmware 2.26
2018.03.16 10:34:02 3: AC_Strom: sending configuration from attributes to device
2018.03.16 10:34:02 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.16 10:34:02 5: AC_Strom: Write: 5,2,1,30a
2018.03.16 10:34:02 5: SW: 5,2,1,30a

2018.03.16 10:34:02 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.16 10:34:02 5: AC_Strom: Write: 2,300,1,1i
2018.03.16 10:34:02 5: SW: 2,300,1,1i

2018.03.16 10:34:02 4: AC_Strom: device sent time: T 74805207 boot at 560^M
2018.03.16 10:34:02 3: AC_Strom: unparseable message from device: P5 falling pullup min 30^M
2018.03.16 10:34:07 3: AC_Strom: device: defined P5 falling pullup min 30^M
2018.03.16 10:34:07 3: AC_Strom: device: intervals set to 2 300 1 1^M
2018.03.16 10:34:12 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:34:12 5: AC_Strom: Write: k
2018.03.16 10:34:12 5: SW: k

2018.03.16 10:34:22 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:34:22 5: AC_Strom: Write: k
2018.03.16 10:34:22 5: SW: k

2018.03.16 10:34:32 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:34:32 5: AC_Strom: Write: k
2018.03.16 10:34:32 5: SW: k

2018.03.16 10:34:34 3: AC_Strom: device didn't reply to k(eeepAlive). Is the right sketch flashed?
2018.03.16 10:34:34 1: 192.168.8.69:80 disconnected, waiting to reappear (AC_Strom)
2018.03.16 10:34:35 1: 192.168.8.69:80 reappeared (AC_Strom)
2018.03.16 10:34:35 3: AC_Strom: device maybe not initialized yet, set timer to send h(ello
2018.03.16 10:34:35 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.16 10:34:35 4: AC_Strom: device reported firmware 2.26
2018.03.16 10:34:35 3: AC_Strom: sending configuration from attributes to device
2018.03.16 10:34:35 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.16 10:34:35 5: AC_Strom: Write: 5,2,1,30a
2018.03.16 10:34:35 5: SW: 5,2,1,30a

2018.03.16 10:34:35 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.16 10:34:35 5: AC_Strom: Write: 2,300,1,1i
2018.03.16 10:34:35 5: SW: 2,300,1,1i

2018.03.16 10:34:35 4: AC_Strom: device sent time: T 74837316 boot at 560^M
2018.03.16 10:34:35 3: AC_Strom: unparseable message from device: P5 falling pullup min 30^M
2018.03.16 10:34:39 3: AC_Strom: device: defined P5 falling pullup min 30^M
2018.03.16 10:34:39 3: AC_Strom: device: intervals set to 2 300 1 1^M
2018.03.16 10:34:45 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:34:45 5: AC_Strom: Write: k
2018.03.16 10:34:45 5: SW: k

2018.03.16 10:34:55 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:34:55 5: AC_Strom: Write: k
2018.03.16 10:34:55 5: SW: k

2018.03.16 10:34:57 3: AC_Strom: device didn't reply to k(eeepAlive). Is the right sketch flashed?
2018.03.16 10:34:57 1: 192.168.8.69:80 disconnected, waiting to reappear (AC_Strom)
2018.03.16 10:34:57 1: 192.168.8.69:80 reappeared (AC_Strom)
2018.03.16 10:34:57 3: AC_Strom: device maybe not initialized yet, set timer to send h(ello
2018.03.16 10:34:57 3: AC_Strom: unparseable message from device: H^M
2018.03.16 10:34:57 3: AC_Strom: device sent hello, V2.26, 0,1,2,5,6,7
2018.03.16 10:34:57 4: AC_Strom: device reported firmware 2.26
2018.03.16 10:34:57 3: AC_Strom: sending configuration from attributes to device
2018.03.16 10:34:57 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.16 10:34:57 5: AC_Strom: Write: 5,2,1,30a
2018.03.16 10:34:57 5: SW: 5,2,1,30a

2018.03.16 10:34:57 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.16 10:34:57 5: AC_Strom: Write: 2,300,1,1i
2018.03.16 10:34:57 5: SW: 2,300,1,1i

2018.03.16 10:34:57 4: AC_Strom: device sent time: T 74859513 boot at 560^M
2018.03.16 10:34:57 3: AC_Strom: unparseable message from device: P5 falling pullup min 30^M
2018.03.16 10:34:57 3: AC_Strom: device: defined P5 falling pullup min 30^M
2018.03.16 10:34:57 3: AC_Strom: device: intervals set to 2 300 1 1^M
2018.03.16 10:35:07 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:35:07 5: AC_Strom: Write: k
2018.03.16 10:35:07 5: SW: k

2018.03.16 10:35:17 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:35:17 5: AC_Strom: Write: k
2018.03.16 10:35:17 5: SW: k

2018.03.16 10:35:27 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:35:27 5: AC_Strom: Write: k
2018.03.16 10:35:27 5: SW: k

2018.03.16 10:35:37 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:35:37 5: AC_Strom: Write: k
2018.03.16 10:35:37 5: SW: k

2018.03.16 10:35:38 5: AC_Strom: Pin 5 debug: adding 1 to long count 6727 and interpolated count 6727
2018.03.16 10:35:38 4: AC_Strom: Pin 5 (pin5) Cnt 697 lCnt 6728 iCnt 6728 (diff 1) in 126.528s, Rej 1, Avg 6363ms, result 0.237
2018.03.16 10:35:38 5: AC_Strom: interval 10:33:31 until 10:35:38
2018.03.16 10:35:38 5: AC_Strom: set readings power5 to 0.237, timeDiff5 to 126528 and countDiff5 to 1
2018.03.16 10:35:38 5: AC_Strom: Device Time 74900.566, Drift 0.325s in 26156.325s, 0.00%
2018.03.16 10:35:47 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:35:47 5: AC_Strom: Write: k
2018.03.16 10:35:47 5: SW: k

2018.03.16 10:35:57 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:35:57 5: AC_Strom: Write: k
2018.03.16 10:35:57 5: SW: k

2018.03.16 10:36:07 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:36:07 5: AC_Strom: Write: k
2018.03.16 10:36:07 5: SW: k

2018.03.16 10:36:17 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:36:17 5: AC_Strom: Write: k
2018.03.16 10:36:17 5: SW: k

2018.03.16 10:36:27 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:36:27 5: AC_Strom: Write: k
2018.03.16 10:36:27 5: SW: k

2018.03.16 10:36:37 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:36:37 5: AC_Strom: Write: k
2018.03.16 10:36:37 5: SW: k

2018.03.16 10:36:47 5: AC_Strom: sending k(eepAlive) to device
2018.03.16 10:36:47 5: AC_Strom: Write: k
2018.03.16 10:36:47 5: SW: k
...


Gruß
Tobias

[StefanStrobel]

Hallo,

anbei ein neuerer Entwicklungsstand.
@Tobias: kannst Du parallel auch einen Wireshark mitlaufen lassen?
Falls Deine Fritzbox keine Informationen zu WLAN Disconnects liefert, dann würde man im Packet-Dump am besten sehen, wer die Verbindung beendet.

Gruss
   Stefan

[tpm88]

Hallo Stefan,

habe den neuen Stand auf Basis 2.31 eingespielt.

Das FritzBox Log hat bei den beobachteten DISCONNECT/CONNECT Ereignissen keine WLAN Ab-/Anmeldung gemeldet. Habe daher jetzt einen tcpdump aufgesetzt. Bisher gab es aber noch keinen neuen Verbindungsabbruch.

Hier für dich noch zur Info das verbose 5 Log vom FHEM Start mit v 2.31 - die doppelte Antwort auf "hello" hängt wohl mit verbose=5 zusammen, oder?

Code Auswählen Erweitern

2018.03.19 08:57:02 3: AC_Strom: Notify called with events: INITIALIZED, open device and set timer to send hello to device
2018.03.19 08:57:02 5: AC_Strom: ArduCounter_Open trying to open connection
2018.03.19 08:57:02 3: Opening AC_Strom device 192.168.8.69:80
2018.03.19 08:57:02 3: AC_Strom device opened
2018.03.19 08:57:02 5: AC_Strom: ArduCounter_Open succeeded - set timer to send hello
...
2018.03.19 08:57:08 0: Server started with 201 defined entities (fhem.pl:16403/2018-03-13 perl:5.020002 os:linux user:fhem pid:2884)
2018.03.19 08:57:08 3: CUL_HM set sd_Test statusRequest
2018.03.19 08:57:08 3: AC_Strom: sending h(ello) to device to ask for version
2018.03.19 08:57:08 5: SW: h

2018.03.19 08:57:09 4: AC_Strom: device reported firmware 2.31 on ESP8266 compiled Mar 18 2018 17:24:08
2018.03.19 08:57:09 3: AC_Strom: device sent Hello message, V2.31 on ESP8266 compiled Mar 18 2018 17:24:08 0,1,2,5,6,7
2018.03.19 08:57:09 4: AC_Strom: device sent time: T 55780733 boot at 560^M
2018.03.19 08:57:09 4: AC_Strom: device sent config for pin 5: 5 falling min pullup
2018.03.19 08:57:09 4: AC_Strom: device reported firmware 2.31 on ESP8266 compiled Mar 18 2018 17:24:08
2018.03.19 08:57:09 3: AC_Strom: device sent Hello message, V2.31 on ESP8266 compiled Mar 18 2018 17:24:08 0,1,2,5,6,7
2018.03.19 08:57:09 4: AC_Strom: device sent time: T 55787409 boot at 560^M
2018.03.19 08:57:09 4: AC_Strom: device sent config for pin 5: 5 falling min pullup

2018.03.19 08:57:11 5: AC_Strom: ConfigureDevice: got running config - comparing
2018.03.19 08:57:11 5: AC_Strom: ConfigureDevice: interval attr not set - take default 30 60 2 2
2018.03.19 08:57:11 5: AC_Strom: ConfigureDevice: comparing interval
2018.03.19 08:57:11 5: AC_Strom: ConfigureDevice: interval does not match (>2 300 1 1< vs >30 60 2 2< from attr)
2018.03.19 08:57:11 3: AC_Strom: sending configuration from attributes to device
2018.03.19 08:57:11 3: AC_Strom: ConfigureDevice calls Attr with interval 2 300 1 1
2018.03.19 08:57:11 5: SW: 2,300,1,1i

2018.03.19 08:57:11 3: AC_Strom: ConfigureDevice calls Attr with pinD5 falling pullup 30
2018.03.19 08:57:11 5: SW: 5,2,1,30a

2018.03.19 08:57:11 3: AC_Strom: device: intervals set to 2 300 1 1^M
2018.03.19 08:57:11 3: AC_Strom: device: defined P5 falling pullup min 30^M

2018.03.19 08:57:12 5: AC_Strom: sending k(eepAlive) to device
2018.03.19 08:57:12 5: SW: k

2018.03.19 08:57:22 5: AC_Strom: sending k(eepAlive) to device
2018.03.19 08:57:22 5: SW: k

2018.03.19 08:57:32 5: AC_Strom: sending k(eepAlive) to device
2018.03.19 08:57:32 5: SW: k

2018.03.19 08:57:42 5: AC_Strom: sending k(eepAlive) to device
2018.03.19 08:57:42 5: SW: k

2018.03.19 08:57:47 5: AC_Strom: Pin 5 debug: adding 1 to long count 10266 and interpolated count 10266
2018.03.19 08:57:47 4: AC_Strom: Pin 5 (pin5) Cnt 960 lCnt 10267 iCnt 10267 (diff 1) in 108.302s, Rej 0, Avg 4530ms, result 0.277
2018.03.19 08:57:47 5: AC_Strom: interval 08:55:58 until 08:57:47
2018.03.19 08:57:47 5: AC_Strom: set readings power5 to 0.277, timeDiff5 to 108302 and countDiff5 to 1
2018.03.19 08:57:47 5: AC_Strom: Initialize clock offset to 1521390441.52977
2018.03.19 08:57:47 5: AC_Strom: Device Time 55825.678, Drift 0.000s in 0.000s
...

Und hier noch ein get info nach dem Start:

Code Auswählen Erweitern

fhem> get AC_Strom info

Status: ArduCounter V2.31 on ESP8266 compiled Mar 18 2018 17:24:08

I2 300 1 1

P5 falling pullup min 30, R5 C963 D0/0 T0 N56269378 X0 S0

M Next report in 289 Milliseconds

Gruß
Tobias

[StefanStrobel]

Hallo Tobias,

das doppelte Hello ist ein Timing-Problem.
Das Modul wartet nach dem Starten und Öffnen der Verbindung 3 Sekunden ob sich ein Gerät mit "Hello" oder "Started" meldet. Danach fragt es explizit nach.
Wenn danach doch noch ein Hello gelesen wird, kommt es zwei mal. Das stört aber nicht weiter und wird bei verbose < 4 auch nicht angezeigt.
Du kannst aber auch das Attribut helloSendDelay auf z.B. 15 setzen, dann wartet das Modul 15 Sekunden...

Gruss
    Stefan

[tpm88]

@Tobias: kannst Du parallel auch einen Wireshark mitlaufen lassen?
Falls Deine Fritzbox keine Informationen zu WLAN Disconnects liefert, dann würde man im Packet-Dump am besten sehen, wer die Verbindung beendet.

Hallo Stefan,

nach fast einer Woche ohne Aussetzer habe ich jetzt mit großer Wahrscheinlichkeit die Ursache gefunden. Unsere Mikrowelle! Diese ist nur selten in Betrieb und verursacht offenbar auch nicht immer dieses Problem. Bei den letzen beiden kurzen Disconnects gestern war sie aber gerade in Betrieb.
Nach meinem Urlaub werde ich schauen, ob ich die Aussetzer reproduzieren kann.

Leider kann ich hierzu (noch) kein Wireshark Protokoll liefern, weil mein Mitschnitt nur 48h gelaufen war. Ich war davon ausgegangen, daß er nach 48h die stündlichen Logs zyklisch überschreibt, aber das war nicht der Fall.

Können bei den kurzen Aussetzern die Zählung von Impulsen verlorengehen oder kann der Sketch damit umgehen?

Ansonsten funktioniert der Zähler auf dem wemos mit der letzten Version top. Kein Vergleich zum PulseCounter und ESPEasy mit dem ich immer wieder falsche Impulse hatte.

Gruß
Tobias

[StefanStrobel]

Hallo Tobias,

Vielen Dank für das Feedback!

Wenn die WLAN-Verbindung unterbrochen ist, zählt der Arducounter normal weiter. Nur wenn die Verbindung in dem Moment weg ist, wenn der Arducounter seinen aktuellen Stand und die Impulse im letzten Intervall an Fhem berichten möchte, kann derzeit etwas verloren gehen.
Da baue ich noch etwas ein um den Bericht dann nachzuholen sobald die Verbindung wieder da ist. Nur bei längeren Unterbrechungen wird das nicht klappen.

Momentan bin ich dabei Firmware-Updates direkt aus Fhem und über WLAN zu ermöglichen.

Gruß
    Stefan

[tpm88]

Hallo Stefan,

jetzt habe ich doch einen tcpdump mit einem Disconnect/Connect von heute morgen.

Hierbei ist der wemos: 192.168.8.69
Und der RPI mit FHEM: 192.168.8.46 (rpi3)

Leider hat der tcpdump keine Zeitstempel - ich denke aber interessant wird es ab Frame 3490. Davor gab es nur ein paar TCP Retransmits.

Danke für die Analyse. Gruß
Tobias

[StefanStrobel]

Hallo Tobias,

Mit tcpdump -nr pcapfile wird es inkl. Zeitstempel angezeigt.
Sieht schon nach gestörter WLAN Verbindung aus.

Gruß
   Stefan

[birdy]

Hallo Stefan
Kann man den Arduino/Adrucounter auch remote, mittels ser2net, an FHEM anschliessen. Also direkt ohne esplink?
Etwa so Arduino -> Pi -> ser2net -> (w)lan -> FHEM

Gruss birdy