HMLAN Adapter wechselt permanent zwischen disconnected / connected

Nobby1805 · 27 Mai 2016, 11:10:49

Mir ist noch etwas aufgefallen ...
unmittelbar vor dem K-Kommando wurde von Fhem etwas an ein HM-Gerät gesendet (Thermostat) ... was bei mir eher selten passiert

Zitat58675 17:13:27.207851000 192.168.1.41 192.168.1.42 TCP 120 4679→1000 [PSH, ACK] Seq=1761 Ack=214609 Win=64767 Len=66
58677 17:13:27.217844000 192.168.1.41 192.168.1.42 TCP 60 4679→1000 [PSH, ACK] Seq=1827 Ack=214609 Win=64767 Len=3

dazu könnte folgender Eintrag im Fhem bei den Device Redaings passen

Zitat2016-05-26 17:13:20 state CMDs_done
2016-05-26 17:13:20 time-request -

die Zeit zwischen dem Fhem-Server und dem Wireshark-Laptop ist nicht exakt synchroniert

Das Paket sieht so aus

Zitat0000 00 1a 22 05 19 c8 00 0a e4 8b c3 d5 08 00 45 00 .."...........E.
0010 00 6a 7b 08 40 00 80 06 fb e1 c0 a8 01 29 c0 a8 .j{.@........)..
0020 01 2a 12 47 03 e8 be b6 3b 19 80 b0 b5 33 50 18 .*.G....;....3P.
0030 fc ff 09 dc 00 00 53 45 44 41 30 38 34 45 34 2c ......SEDA084E4,
0040 30 30 2c 30 30 30 30 30 30 30 30 2c 30 31 2c 45 00,00000000,01,E
0050 44 41 30 38 34 45 34 2c 37 34 38 30 33 46 32 41 DA084E4,74803F2A
0060 45 44 41 32 33 35 42 36 30 46 30 32 30 34 31 45 EDA235B60F02041E
0070 44 39 43 46 31 30 0d 0a D9CF10..

Rampler · 28 Mai 2016, 18:16:10

Zitat von: Nobby1805 am 27 Mai 2016, 09:44:19
Fhem sendet ja im Normalfall (unveränderter wdTimer) alle 25 Sekunden ein K-Kommando an den HMLAN. Das ist im Log auch sehr gut zu sehen
Allerdings ist das letzte Paket, das vor dem Reboot an den HMLAN gesendet wird ein K-Kommando ... und das wird dann, weil der HMLAN nicht acknowledged, mehrfach retransmittet. Was jetzt interessant ist ist, dass dieses K-Kommando nicht 25 Sekunden nach dem vorherigen geschickt worden ist, sondern schon nach 13,4 Sekunden gibt es einen Grund, aus dem ein K-Kommando schon vorzeitig verschickt wird ?

Hallo Nobby,
so wie ich das sehe, braucht doch der HM-Lan Adapter mind. alle 30 Sec. ein K-Command, sonst folgt ein disconnect. Folglich sind die 13,4 Sec. doch eher besser, zumindest was die disconnects angeht.
Gibst schon was neues ?
mfg Klaus

Nobby1805 · 28 Mai 2016, 19:04:36

Hallo Klaus,

nein, ich warte jetzt auf ein zweites Auftreten um die beiden zu vergleichen ...

Wenn alle 30 Sekunden ein K-Kommando benötigt wird dann ist alles kleiner 29 nicht besser sondern verringert nur die Wahrscheinlichkeit, dass durch eine Verzögerung ein Timeout passiert.

Mir geht es im Prinzip erst mal darum, ob es einen Grund gibt dass das Kommando schon vorab geschickt worden ist. ES ist ja schon "komisch", dass das in direktem Zusammenhang mit dem Reboot steht.

Gruß Norbert

PS ich hoffe jetzt nur, dass mein Uralt-Laptop mit Wireshark (auf Windows XP) überlebt, einmal hat er sich vermutlich aus Wärmegründen schon aufgehängt
PPS ich bin übrigens der Meinung, dass das mit den 30 Sekunden nicht ganz richtig ist ... der HMLAN disconnectet, wenn er 30 Sekunden weder etwas gesendet noch etwas empfangen hat ... man könnte also auch den Timer bei jedem bearbeiteten Paket wieder zurücksetzen.

Rampler · 28 Mai 2016, 19:10:32

Zitat von: Nobby1805 am 28 Mai 2016, 19:04:36
Es ist ja schon "komisch", dass das in direktem Zusammenhang mit dem Reboot steht.

100 % agree

Nobby1805 · 30 Mai 2016, 12:52:46

Zitat von: Nobby1805 am 27 Mai 2016, 09:44:19
Ich habe mir den Log etwas genauer angesehen und das bringt mich zu einer Frage an Martin!!

Fhem sendet ja im Normalfall (unveränderter wdTimer) alle 25 Sekunden ein K-Kommando an den HMLAN. Das ist im Log auch sehr gut zu sehen

Allerdings ist das letzte Paket, das vor dem Reboot an den HMLAN gesendet wird ein K-Kommando ... und das wird dann, weil der HMLAN nicht acknowledged, mehrfach retransmittet. Was jetzt interessant ist ist, dass dieses K-Kommando nicht 25 Sekunden nach dem vorherigen geschickt worden ist, sondern schon nach 13,4 Sekunden gibt es einen Grund, aus dem ein K-Kommando schon vorzeitig verschickt wird ?

PS wenn genauere Informationen aus dem Log benötigt werden kann ich die gerne liefern

Heute ist nach 85:00 Stunden das Problem wieder aufgetreten, die Situation vor dem Absturz des HMLAN sieht sehr ähnlich aus.

Wieder ist ein Kommando an einen Thermostaten gesendet worden (vermutlich Zeit setzen) und wieder wurde unmittelbar danach ein K-Kommando geschickt, das dann auf TCP-Ebene nicht mehr quittiert (und daher retransmittet) worden ist.

K-Kommando 6:13:40.404
Antwort des HMLAN um 6:13:40.410
Empfange Daten vom HMLAN um 6:13:41.651
Sende Daten an HMLAN um 6:13:41.748
erneute K-Kommando um 6:13:41.772 (also 1,3 Sekunden nach dem vorherigen)

Ich habe den Wireshark-Log wieder über ELV an eQ-3 geschickt

mgernoth · 30 Mai 2016, 15:37:24

Hi,

Zitat von: Nobby1805 am 30 Mai 2016, 12:52:46
Wieder ist ein Kommando an einen Thermostaten gesendet worden (vermutlich Zeit setzen) und wieder wurde unmittelbar danach ein K-Kommando geschickt, das dann auf TCP-Ebene nicht mehr quittiert (und daher retransmittet) worden ist.

Was passiert denn, wenn man das KeepAlive nach 10 Sendevorgaengen im Code disabled?

Code Auswählen


Index: 00_HMLAN.pm
===================================================================
--- 00_HMLAN.pm	(revision 11566)
+++ 00_HMLAN.pm	(working copy)
@@ -891,7 +891,7 @@
   syswrite($hash->{TCPDev}, $msg)     if($hash->{TCPDev});
   if ($hash->{helper}{q}{scnt} == 10){
     $hash->{helper}{q}{scnt} = 0;
-    HMLAN_KeepAlive("x:$name") ;
+    #HMLAN_KeepAlive("x:$name") ;
   }
 }

Evtl. kommt dieses K zu schnell während der HMLAN gerade noch mit dem vorherigen Kommando bzw. dessen Antwort beschäftigt ist.

Viele Grüße
Michael

Nobby1805 · 30 Mai 2016, 16:53:29

Das könnte man mal probieren ... aber dann müsste man sehr lange warten, ob es nicht doch noch passiert $:-\$
Oder man ändert von 10 auf einen kleineren Wert, dann müsste es doch öfter passieren ?

Warum wird das denn überhaupt gemacht ?

UND vermutlich sind wir uns einig, dass das bei einer sauberen Programmierung im HMLAN aber NICHT zu einem Crash führen dürfte

mgernoth · 30 Mai 2016, 17:25:35

Hi,

Zitat von: Nobby1805 am 30 Mai 2016, 16:53:29
Das könnte man mal probieren ... aber dann müsste man sehr lange warten, ob es nicht doch noch passiert $:-\$
Oder man ändert von 10 auf einen kleineren Wert, dann müsste es doch öfter passieren ?

Ja, teste es evtl. mal mit 1.

Zitat
Warum wird das denn überhaupt gemacht ?

Das ganze kam am 24.6.2015 in Fhem und hatte als Log-Eintrag "00_HMLAN: regular read IO load".

IIRC begannen danach dann auch die HMLAN-Disconnectes beim Ansteuern der HM-OU-LED16. In dem Log, das ich gerade gefunden habe, war der Auslöser auch das "K" während eines laufenden Sendevorgangs: https://forum.fhem.de/index.php/topic,41024.msg334302.html#msg334302

Zitat
UND vermutlich sind wir uns einig, dass das bei einer sauberen Programmierung im HMLAN aber NICHT zu einem Crash führen dürfte

Da stimme ich Dir voll und ganz zu, das müsste eQ-3 fixen (die Hoffnung stirbt zuletzt)...

Aber evtl. kann hier Martin im 00_HMLAN-Code einen Workaround bauen, damit die "K"s nicht gesendet werden, solange ein "S"endevorgang läuft. Die "normalen" Keepalives alle 25 Sekunden können übrigens auch zufällig genau zum falschen Zeitpunk kommen und den Crash auslösen, das ist aber deutlich unwahrscheinlicher.

Viele Grüße
Michael

mgernoth · 31 Mai 2016, 00:24:32

Hallo,

so, jetzt habe ich 00_HMLAN.pm mal so umgebaut, dass ein K niemals einen laufenden Sendevorgang unterbrechen kann. Bitte mal testen und schauen, ob dieser Patch die Probleme behebt.

@Martin: Schau mal bitte drueber, ich bin mir nicht sicher, ob ich das "sending" ueberall wieder auf 0 setze, wo es sein muss (nach "R" und wenn ein HMLAN (re-)connected).

Viele Gruesse
Michael

Nobby1805 · 31 Mai 2016, 17:19:57

Ich habe gerade von ELV eine Mail bekommen, dass das Problem reproduziert werden konnte und die Entwicklungsabteilung an einem Fix arbeitet.

Das ist die gute Nachricht, jetzt bleibt nur zu hoffen, dass die Veröffentlichung nicht wieder so lange wie bei der Version 0.965 dauert.

@mgernoth: dein neues Module wollte ich erst mal absichtlich nicht aktivieren, weil ich ja weitere Logs an eQ-3 senden wollte ... aber das hat sich ja jetzt erledigt.

Btw. ich hatte die Grenze auf 3 reduziert ... aber nichts ist passiert ... vielleicht aber deshalb, weil ich gleichzeitig verbose am HMLAN auf 5 gesetzt habe (ja, ich weiß, man sollte nie an mehreren Stellen gleichzeitig "drehen"

) ... dadurch scheint sich das Timing leicht (aber entscheidend) zu ändern

MaxAut · 06 Juni 2016, 23:41:17

Hallo alle!

Ich hoffe ich bin hier nicht falsch; habe das auch in einem anderen Thread gepostet, bevor ich über diesen hier gestolpert bin. habe auch dieses Problem: Mein HM-CFG-LAN Adapter rebootet (uptime geht auf 0) allerdings alle paar Minuten!

Bei mir läuft FHEM auf einer Synology DS414, und ist eine komplett neue Installation (ich steige gerade von einer reinen CCU2 basierenden Lösung auf FHEM um und bin Neuling).

Das habe ich bereits gemacht:
- Aktivierung des zweiten NICs auf der DS414, Vergabe einer eigenen IP in einem neuen Subnetz, und anschließen des HM-CFG-LAN Adapters an diesem Interface (direkt, ohne Switch dazwischen).
Die Verbindung klappt, die Reboots bleiben.

- Einstelllen dieses Interfaces auf 10Mbit/half Duplex und auto nego deaktivieren.
Kein Unterschied

Und so sieht das bei mir im Log aus:
2016.06.06 23:29:26 1: 192.168.240.123:1000 disconnected, waiting to reappear (HMLAN0)
2016.06.06 23:29:26 1: HMLAN_Parse: HMLAN0 new condition disconnected
2016.06.06 23:29:26 1: 192.168.240.123:1000 reappeared (HMLAN0)
2016.06.06 23:29:26 1: HMLAN_Parse: HMLAN0 new condition init
2016.06.06 23:29:26 1: HMLAN_Parse: HMLAN0 new condition ok
2016.06.06 23:33:36 1: 192.168.240.123:1000 disconnected, waiting to reappear (HMLAN0)
2016.06.06 23:33:36 1: HMLAN_Parse: HMLAN0 new condition disconnected
2016.06.06 23:33:36 1: 192.168.240.123:1000 reappeared (HMLAN0)
2016.06.06 23:33:36 1: HMLAN_Parse: HMLAN0 new condition init
2016.06.06 23:33:36 1: HMLAN_Parse: HMLAN0 new condition ok
2016.06.06 23:34:26 1: 192.168.240.123:1000 disconnected, waiting to reappear (HMLAN0)
2016.06.06 23:34:26 1: HMLAN_Parse: HMLAN0 new condition disconnected
2016.06.06 23:34:27 1: 192.168.240.123:1000 reappeared (HMLAN0)
2016.06.06 23:34:27 1: HMLAN_Parse: HMLAN0 new condition init
2016.06.06 23:34:27 1: HMLAN_Parse: HMLAN0 new condition ok

Liebe Grüße,
Max

LuckyDay · 07 Juni 2016, 00:32:31

schau mal im Fhem wiki, wie man das AES mit der Homematic Konfigurator auf den Lanseite auschaltet

MaxAut · 07 Juni 2016, 00:35:56

AES ist auf der LAN-Seite deaktiviert. Ich habe die Firmware des Adapters upgedatet, die IP fixiert, und AES abgedreht; das waren die ersten Schritte, noch bevor ich die erste Verbindung mit FHEM hergestellt hatte.

ps: Die Kommunikation mit HM Devices funktioniert ja auch, sofern der Adapter nicht gerade neu startet ...

LuckyDay · 07 Juni 2016, 00:46:09

dann mußt du sniffen wie im Wiki beschrieben
, und zeige ein list von dem HmLan adapter
ich hasse Textaufgaben ohne Ihnhalt, auf deutsch will sehen was du auf dem Bildschirm siehst.

ich würde einen eigenen Beitrag aufmachen, hat hier mit dem Problem nichts zu tun.

MaxAut · 07 Juni 2016, 01:10:21

Ich stelle gerne jeder Information zu Verfügung. Ich bin halt Anfänger, und weiß nicht was gebraucht wird. Unten der Output von dem List.

Soweit ich Nobby verstanden habe (auch aus anderen Threads, bzw. seiner Diskussion zu dem Thema auf der ELV Webseite), hat er genau das selbe Problem wie ich: Der Adapter rebootet aus unerklärlichen Gründen. Bei mir halt deutlich häufiger als bei ihm.

Sniffen wird schwierig, da der Adapter, wie bereits geschrieben, direkt, ohne Switch, an der Synology hängt. Ich kann ihn zwar wieder normal, an den Switch, anhängen, das hilft nur nichts, da ich zu Hause nicht über managebare Switches verfüge, auf denen ich Ports spiegeln könnte. Ich werde aber mal mit tcpdump auf der Synology experimentieren. Da sollte man ja alles mitbekommen, da wie gesagt der Adapter direkt an dem zweiten Interface angeschlossen ist.

Internals:
DEF 192.168.240.123:1000
DeviceName 192.168.240.123:1000
FD 4
HMLAN0_MSGCNT 645
HMLAN0_TIME 2016-06-07 01:01:47
IFmodel LAN
NAME HMLAN0
NR 24
NTFY_ORDER 50-HMLAN0
PARTIAL
RAWMSG E3740BA,0000,00025BD5,FF,FFA3,BE86533740BA000000004100B24200B543FFFD440003
RSSI -93
STATE opened
TYPE HMLAN
XmitOpen 1
assignedIDsCnt 3
msgKeepAlive dlyMax:0.03 bufferMin:4
msgLoadCurrent 1
msgLoadHistory 5min steps: 0/0/0/0/0/0/0/0/0/0/0/0
msgParseDly min:-9 max:23 last:12 cnt:315
owner 351B6A
owner_CCU VCCU
uptime 000 00:02:34.581
Readings:
2016-06-06 22:46:05 D-HMIdAssigned 351B6A
2016-06-06 22:46:05 D-HMIdOriginal 3223F1
2016-06-06 22:46:05 D-firmware 0.964
2016-06-06 22:46:05 D-serialNr LEQ0986111
2016-06-07 01:00:16 Xmit-Events timeout:15 ok:38 disconnected:38 init:38
2016-06-07 01:00:16 cond ok
2016-06-07 01:01:31 loadLvl low
2016-06-07 00:59:10 prot_disconnected last
2016-06-07 01:00:16 prot_init last
2016-06-07 01:00:16 prot_ok last
2016-06-07 00:59:10 prot_timeout last
2016-06-07 01:00:16 state opened
Helper:
assIdCnt 3
assIdRep 3
info 03C4,LEQ0986111,3223F1,351B6A
setTime 44716
Bm:
Hmlan_get:
cnt 3
dmx 0
mAr
max 0
tot 0
Hmlan_notify:
cnt 670
dmx 0
max 14
tot 95
mAr:
HASH(0x1698e98)
HASH(0x1698e98)
Hmlan_read:
cnt 961
dmx 0
max 362
tot 5273
mAr:
HASH(0x1698e98)
Hmlan_ready:
cnt 785
dmx 0
max 3120
tot 42524
mAr:
HASH(0x1698e98)
Hmlan_set:
cnt 76
dmx 0
mAr
max 0
tot 0
Cnd:
0 38
252 15
253 38
255 38
Dly:
cnt 315
lst 12
max 23
min -9
Ids:
38668d:
cfg +38668D,00,01,00
name TFKontaktSZLinks
3866b9:
cfg +3866B9,02,01,00
chn 00
flg 0
msg
name TFKontaktSZRechts
to 1465251551.08803
38671a:
cfg +38671A,00,01,00
chn 01
flg 0
msg
name TFKontaktWZ
to 1465250203.69884
K:
BufMin 4
DlyMax 0.03
Next 1465254116.17412
Start 1465254091.17412
Loadlvl:
bl 40
a:
99
90
40
0
H:
0 low
40 batchLevel
90 high
99 suspended
Log:
all 0
sys 0
ids:
ARRAY(0x169a4f0)
Q:
HMcndN 0
answerPend 0
hmLanQlen 1
keepAliveRec 1
keepAliveRpt 0
loadLast 1
loadNo 0
scnt 0
apIDs:
Ref:
drft -0.000159936025589764
hmtL 137856
kTs 0
offL 1465253953321
sysL 1465254091177
Attributes:
hmId 351B6A
hmLanQlen 1_min
loadLevel 0:low,40:batchLevel,90:high,99:suspended