HMLAN disconnect

[PatrickR]

Mahlzeit!

Ich hatte vor einiger Zeit häufige Disconnects meines HM-CFG-LAN-Adapters. Nach einer ausgiebigen Performanceoptimierung trat das Problem über Monate nicht mehr auf. Inzwischen ist das Problem wieder aktuell und scheint mit einer Performanceoptimierung nicht mehr behebbar zu sein:

Code Auswählen Erweitern


2015.08.22 18:03:25.192 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:25.194 5: HMLAN/RAW: /HHM-LAN-IF,03C4,KEQ0852354,23A665,23A665,0E5A2071,003B,02
2015.08.22 18:03:25.195 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:KEQ0852354 d:23A665 O:23A665 t:0E5A2071 IDcnt:003B L:2 %
2015.08.22 18:03:25.740 5: HMLAN/RAW: /E2398FF,0000,0E5A2289,FF,FFC1,2886702398FF000000010A2E
2015.08.22 18:03:25.740 5: HMLAN_Parse: HMLAN1 R:E2398FF   stat:0000 t:0E5A2289 d:FF r:FFC1     m:28 8670 2398FF 000000 010A2E
2015.08.22 18:03:25.740 5: HMLAN1 dispatch A0C2886702398FF000000010A2E::-63:HMLAN1
2015.08.22 18:03:26.737 5: HMLAN/RAW: /E22261F,0000,0E5A266E,FF,FFC7,DD861022261F0000000AB1050B0018
2015.08.22 18:03:26.737 5: HMLAN_Parse: HMLAN1 R:E22261F   stat:0000 t:0E5A266E d:FF r:FFC7     m:DD 8610 22261F 000000 0AB1050B0018
2015.08.22 18:03:26.737 5: HMLAN1 dispatch A0FDD861022261F0000000AB1050B0018::-57:HMLAN1
2015.08.22 18:03:29.731 5: HMLAN/RAW: /E206DFC,0000,0E5A3221,FF,FFD7,97A440206DFC1111110C0F
2015.08.22 18:03:29.732 5: HMLAN_Parse: HMLAN1 R:E206DFC   stat:0000 t:0E5A3221 d:FF r:FFD7     m:97 A440 206DFC 111111 0C0F
2015.08.22 18:03:29.732 5: HMLAN1 dispatch A0B97A440206DFC1111110C0F::-41:HMLAN1
2015.08.22 18:03:29.821 5: HMLAN_Send:  HMLAN1 S:S56268894 stat:  00 t:00000000 d:01 r:56268894 m:97 8002 111111 206DFC 010C0000
2015.08.22 18:03:29.831 1: N_R_OG.WZ.RC19B_1 Name: OG.WZ.RC19B_1Btn_12, Event: Short (to OG.WZ.RC19B_1), button:12, event:Short
2015.08.22 18:03:29.835 3: CUL_HM set OG.WZ.LadegeraetSessel on-for-timer 10800
2015.08.22 18:03:29.836 5: HMLAN_Send:  HMLAN1 S:+22A8DA,00,01,00
2015.08.22 18:03:29.836 5: HMLAN_Send:  HMLAN1 S:S562688FA stat:  00 t:00000000 d:01 r:562688FA m:03 A011 23A665 22A8DA 0201C80000D2E6
2015.08.22 18:03:34.114 5: HMLAN_Send:  HMLAN1 S:S562699B1 stat:  00 t:00000000 d:01 r:562699B1 m:03 A011 23A665 22A8DA 0201C80000D2E6
2015.08.22 18:03:39.002 5: HMLAN_Send:  HMLAN1 S:S5626ACC8 stat:  00 t:00000000 d:01 r:5626ACC8 m:03 A011 23A665 22A8DA 0201C80000D2E6
2015.08.22 18:03:44.723 5: HMLAN_Send:  HMLAN1 S:S5626C321 stat:  00 t:00000000 d:01 r:5626C321 m:03 A011 23A665 22A8DA 0201C80000D2E6
2015.08.22 18:03:50.192 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:51.193 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:52.193 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:53.194 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:54.195 1: HMLAN_Parse: HMLAN1 new condition timeout
2015.08.22 18:03:54.203 1: hmcfglan1:1000 disconnected, waiting to reappear (HMLAN1)
2015.08.22 18:03:54.204 1: HMLAN_Parse: HMLAN1 new condition disconnected
2015.08.22 18:03:54.728 1: hmcfglan1:1000 reappeared (HMLAN1)
2015.08.22 18:03:54.728 5: HMLAN_Send:  HMLAN1 I:A23A665
2015.08.22 18:03:54.728 5: HMLAN_Send:  HMLAN1 I:C
2015.08.22 18:03:54.728 5: HMLAN_Send:  HMLAN1 I:+2624F1,00,01,00
2015.08.22 18:03:54.728 5: HMLAN_Send:  HMLAN1 I:+208424,00,01,00
2015.08.22 18:03:54.728 5: HMLAN_Send:  HMLAN1 I:+20CE4D,00,01,00
2015.08.22 18:03:54.728 5: HMLAN_Send:  HMLAN1 I:+238B31,00,01,00
2015.08.22 18:03:54.728 5: HMLAN_Send:  HMLAN1 I:+22F005,00,01,00
2015.08.22 18:03:54.729 5: HMLAN_Send:  HMLAN1 I:+2589BD,00,01,00
2015.08.22 18:03:54.729 5: HMLAN_Send:  HMLAN1 I:+222CED,00,01,00
2015.08.22 18:03:54.729 5: HMLAN_Send:  HMLAN1 I:+2640D1,00,01,00


Das Keep-Alive vor dem Disconnect scheint pünktlich nach 25 Sekunden statt zu finden.

Hier der Vollständigkeit halber die Ausgabe von Apptime:

Code Auswählen Erweitern


name             function    max  count    total  average maxDly
                              HMLAN1           HMLAN_Read   6915  78217   679044     8.68      0 HASH(HMLAN1)
                               DbLog            DbLog_Log   6909 102677   188234     1.83      0 HASH(DbLog); HASH(OG.BZ.Heizung_Clima)
                 tmr-HMLAN_KeepAlive     keepAlive:HMLAN1   4660  12764    39909     3.13   4786 keepAlive:HMLAN1
                              HMLAN1          HMLAN_Ready   3002    332     3040     9.16      0 HASH(HMLAN1)
                       OG.WZ.Harmony         harmony_Read   1923   6595     2142     0.32      0 HASH(OG.WZ.Harmony)
                         OG.WO.VR100   VORWERK_VR100_Read   1635  16783    15343     0.91      0 HASH(OG.WO.VR100)
                         tmr-at_Exec      HASH(0x22a64e0)   1058      3     2712   904.00      5 HASH(A_TempListSave)
                        D_hminfo_err          DOIF_Notify   1044 102677     7530     0.07      0 HASH(D_hminfo_err); HASH(hminfo)
                         Pushover_pr         Pushover_Set   1038     27     7497   277.67      0 HASH(Pushover_pr); Pushover_pr; msg; "HMInfo"; "OK"; ""; 0; ""
               tmr-HMinfo_autoUpdate         sUpdt:hminfo    871    532    10139    19.06    535 sUpdt:hminfo
                 tmr-Calendar_Wakeup      HASH(0x2b8b120)    857    178     3774    21.20    808 HASH(CAL_pr)
      N_OG.BZ.WaschmaschineInBetrieb          notify_Exec    813 102677     1983     0.02      0 HASH(N_OG.BZ.WaschmaschineInBetrieb); HASH(OG.BZ.Waschmaschine_Pwr)
                         Pushover_jv         Pushover_Set    807      3      807   269.00      0 HASH(Pushover_jv); Pushover_jv; msg; "Waschmaschine"; "Fertig!"; ""; 0; "bike"
                 tmr-Calendar_Wakeup      HASH(0x2a18f28)    782    177     3225    18.22    928 HASH(CAL_prjv)
                      FensterTuerenX     structure_Notify    614 102677     1989     0.02      0 HASH(FensterTuerenX); HASH(OG.AZ.Fenster)
                        OG.WZ.Lampen     structure_Notify    573 102677      673     0.01      0 HASH(OG.WZ.Lampen); HASH(OG.WZ.Stehlampe2)
                         Presence_pr        PRESENCE_Read    542   5324      631     0.12      0 HASH(Presence_pr)
                       FensterTueren     structure_Notify    529 102677     1049     0.01      0 HASH(FensterTueren); HASH(OG.WO.Eingangstuer)
          tmr-Weather_GetUpdateTimer      HASH(0x2b16f28)    243    355     6200    17.46    815 HASH(XX.XX.Wetter)
                          RG_Heizung readingsGroup_Notify     90 102677    17408     0.17      0 HASH(RG_Heizung); HASH(OG.SZ.Thermostat_Climate)
                   N_OG.BZ.Steckdose          notify_Exec     89     25      351    14.04      0 HASH(N_OG.BZ.Steckdose); HASH(OG.BZ.Steckdose)


Das Problem tritt sporadisch auf, jedoch ausschließlich bei Verwendung meiner RC19B-Fernbedienung. Das Setup ist wie folgt: Die Kanäle der Fernbedienung (OG.WZ.RC19B_1, 206DFC) sind mit Kanälen eines virtuellen Homematic-Geräts (OG.WZ.RC19B_1V, 111111) gepeert. Wird einer der Knopfdrücke erkannt löst ein Notify einen Schaltvorgang eines Homematic-Geräts aus. Bei der Fehlersituation leuchtet die rote LED der Fernbedienung und es erscheint CO-ER.

Hier noch der erste Teil von list HMLAN1:

Code Auswählen Erweitern


Internals:
   CHANGED
   DEF        hmcfglan1:1000
   DeviceName hmcfglan1:1000
   FD         10
   HMLAN1_MSGCNT 70678
   HMLAN1_TIME 2015-08-25 20:28:43
   NAME       HMLAN1
   NR         60
   NTFY_ORDER 50-HMLAN1
   PARTIAL
   RAWMSG     E2642EA,0000,0F4BB317,FF,FFCC,0A84702642EA000000010032
   RSSI       -52
   STATE      opened
   TYPE       HMLAN
   XmitOpen   1
   assignedIDsCnt 59
   msgKeepAlive dlyMax:4.786 bufferMin:0
   msgLoadCurrent 1
   msgLoadHistory 5min steps: 0/0/0/1/0/0/0/0/-1/0/0/0
   msgParseDly min:-18 max:6804 last:17 cnt:70527
   owner      23A665
   owner_CCU  vccu
   uptime     002 71:16:59.287
   CHANGETIME:
   Helper:
     Dblog:
       Xmit-events:
         Dblog:
           TIME       1440270791.12364
           VALUE      disconnected:3 init:3 ok:3 timeout:2
       Cond:
         Dblog:
           TIME       1440270791.12364
           VALUE      ok
       Loadlvl:
         Dblog:
           TIME       1440238665.28969
           VALUE      low
       State:
         Dblog:
           TIME       1440270791.01883
           VALUE      CONNECTED
   Readings:
     2015-08-21 20:21:08   D-HMIdAssigned  23A665
     2015-08-21 20:21:08   D-HMIdOriginal  23A665
     2015-08-21 20:21:08   D-firmware      0.964
     2015-08-21 20:21:08   D-serialNr      KEQ0852354
     2015-08-22 21:13:11   Xmit-Events     disconnected:3 init:3 ok:3 timeout:2
     2015-08-22 21:13:11   cond            ok
     2015-08-25 20:28:21   loadLvl         low
     2014-03-01 16:40:37   prot_ERROR-Overload last
     2014-03-11 00:00:54   prot_Warning-HighLoad last
     2015-08-22 21:12:07   prot_disconnected last
     2015-08-22 21:13:11   prot_init       last
     2014-10-10 22:01:56   prot_keepAlive  last
     2015-08-22 21:13:11   prot_ok         last
     2015-08-22 21:12:07   prot_timeout    last
     2015-08-22 21:13:11   state           opened


Für einen Tipp zur Lösung des WAF-senkenden Problems wäre ich sehr dankbar. Gerne liefere ich auch weitere Logs/Daten nach.

Patrick

[Nobby1805]

Diese Sequenz

Code Auswählen Erweitern


2015.08.22 18:03:50.192 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:51.193 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:52.193 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:53.194 5: HMLAN_Send:  HMLAN1 I:K
2015.08.22 18:03:54.195 1: HMLAN_Parse: HMLAN1 new condition timeout
2015.08.22 18:03:54.203 1: hmcfglan1:1000 disconnected, waiting to reappear (HMLAN1)
2015.08.22 18:03:54.204 1: HMLAN_Parse: HMLAN1 new condition disconnected
2015.08.22 18:03:54.728 1: hmcfglan1:1000 reappeared (HMLAN1)

entsteht nach meiner Erfahrung durch einen Reboot des HMLAN was auch dies hier zeigt

Code Auswählen Erweitern

Internals:

   HMLAN1_TIME 2015-08-25 20:28:43

   uptime     002 71:16:59.287

ich habe bei meinem HMLAN Reboots im Abstand von wenigen Minuten bis maximal 1-2 Tagen ... der Grund ist unklar. ELV hat schon vor einiger Zeit dazu ein Ticket bei e-Q3 erstellt, bisher leider ohne Ergebnis 

[franky08]

Netzwerk kontrollieren! Den HMLAN mal direkt mit dem Router verbinden und deine fhem Instanz auch direkt auf den Router legen. Ich habe 3 hmlan im Einsatz und immer gesucht, warum der hmlan1 oft auf disconnect geht, es lag am Netzwerk. Der hmlan1 war über einen extra Switch zusammen mit meinen 3 fhem Instanzen verbunden, nachdem ich den hmlan1 direkt auf den Router gelegt hatte sind diese disconnects verschwunden.
Vielleicht bringt´s ja was 

VG
Frank

[PatrickR]

Netzwerk kontrollieren! [...]
Vielleicht bringt´s ja was 

Leider nein. Habe den HMLAN an den zentralen Switch gehängt. Neues CAT6A Patchkabel, keine Errors auf dem Port. Dennoch ist gerade wieder der Disconnect aufgetreten.

Hatte die Hoffnung, dass das Log Aufschluss gibt.

Patrick

[franky08]

Dann starte mal apptime, vlt. Bekommst du dann Antwort, was den hmlan zum disconnect bringt. Keep Alive passiert alle 30 sec. Und wenn der hmlan in dieser Zeit nicht antwortet dann kommt ein disconnect.

VG
Frank

[PatrickR]

Dann starte mal apptime, vlt. Bekommst du dann Antwort, was den hmlan zum disconnect bringt. Keep Alive passiert alle 30 sec. Und wenn der hmlan in dieser Zeit nicht antwortet dann kommt ein disconnect.

Schau mal in mein Eröffnungsposting. Das "I" kommt exakt nach 25s, wie eingestellt.

Patrick

[franky08]

Sorry, hab ich nicht gesehen.

[frank]

Das "I" kommt exakt nach 25s, wie eingestellt.

genau genommen "geht" das "I". ob es beim hmlan angekommen ist, kannst du daraus nicht erkennen. wenn keine antwort kommt, ist was faul und es gibt wiederholungen. und ob die logzeiten exakt zu den sendezeiten passen, würde ich nicht drauf wetten. 

wenn du genau weisst, was los ist, verstehe ich deine aussagen nicht.

[Nobby1805]

Leider nein. Habe den HMLAN an den zentralen Switch gehängt. Neues CAT6A Patchkabel, keine Errors auf dem Port. Dennoch ist gerade wieder der Disconnect aufgetreten.

Hatte die Hoffnung, dass das Log Aufschluss gibt.

Patrick

und was sagt jetzt die uptime des HMLAN? Neu gebootet? Hast du IP-TV, z.B. Entertain, in deinem Netz?

[frank]

und was sagt jetzt die uptime des HMLAN? Neu gebootet?

neu booten kann man ggf auch sehr schön an der load erkennen, da diese beim booten auf 0 gesetzt wird. bei mir geschieht dies immer im zusammenhang mit condition=timeout.

[Nobby1805]

neu booten kann man ggf auch sehr schön an der load erkennen, da diese beim booten auf 0 gesetzt wird. bei mir geschieht dies immer im zusammenhang mit condition=timeout.

das ist aber m.E. eine Folge des disconnects ... ob der HMLAN gebootet hat erkennt man an der uptime diese wird bei jedem Datenpakte vom HMLAN mit gesendet

[PatrickR]

OK, es ist tatsächlich ein Reboot. Sorry, hatte die Info mit der Uptime komplett übersehen.

Die Frage ist, wie ich mit das Problem in den Griff bekomme.

Mir fallen ein:
-CUL/hmland
-2. HMLAN in Unkenntnis, ob beim Disconnect der verbleibende HMLAN einspringt.
-diverse gtässliche Workarounds

Wie geht Ihr anderen Reboot-Geplagten damit um? Auf eq3 zu warten halte ich für nicht sehr aussichtsreich. Schließlich muss der HMLAN ja lediglich mit der eq3-Software laufen.


Von unterwegs gesendet.

[frank]

@nobby
bei einfachen disconnects wird die load nicht zurueck gesetzt. nur beim reboot.

@patrick
freezes in fhem reduzieren. mit hilfe apptime und perfmon. eventuell saemtliche lan aktivitaeten in zweite fhem instanz auslagern. lan zwischen fhem und hmlan sauber halten. ich nutze zusaetzlich ein hmusb, der ueber die vccu die aufgaben des hmlan im problemfall uebernimmt. extra 2 unterschiedliche interfaces um interfaceprobleme zu umgehen.
es gibt auch problemdevices. beim sync der zeit meiner hm-cc-tc, kurz nach mitternacht, hat der hmlan fast immer einen timeout/reboot gemacht. der hmusb noch nie. es gibt auch user, die mehr disconnects mit. dem hmusb haben. ein bisschen voodoo ist schon im spiel.

[frank]

ach so... dein apptime zeigt doch ziehmlich eindeutig 7 sec im zusammenhang mit dblog. schon mal untersucht warum? ein "sauberes" fhem, sollte nichts ueber 1 sek zeigen. vielleicht sogar weniger?

[justme1968]

wenn es an dblog liegt schau
mal ob du das DbLogType attribut gesetzt hast. die beste performance bekommst du wenn du es auf  History setzt.

gruss
  andre