HM-TC-IT-WM-W-EU lief Amok (Overload)

[alanblack]

Hallo Community,

heute Vormittag bekam ich die Nachricht, dass eines meine HM-CFG-LAN in den Overload gegangen ist. Ein "protoEventsShort" ergab, dass dies ~27000 Nachrichten an ein HM-TC-IT-WM-W-EU geschickt hatte, welches beim Arbeiten auf einen Fehler gelaufen zu sein schien - genauer: Register Read timeout. Das lies sich per VPN nicht beheben. Da ich nicht vor Ort war, hieß es: abwarten! Zum Glück passierte danach nichts weiteres, so dass der Rest des Hauses normal weiterlief und alle HM-CFG-LAN auch wieder beim Status ok ankamen.
Abends dann nochmal: alles, was ich dem HM-TC-IT-WM-W-EU schickte, kam nicht an. Auch

Code Auswählen Erweitern


set clear msgEvents
get getconfig

mit Tastendruck am HM-TC-IT-WM-W-EU half nicht; wieder der timeout. Erst das Ganze nochmal nach dem Batterie-rein-raus brachte den HM-TC-IT-WM-W-EU zurück in die Spur.
Ich habe mal ein paar Begriffe hier in die Suche getippt, habe dazu aber keine brauchbaren Hinweise
Damit mit nicht so ein Ding - frei nach Murphy: - schlimmstenfalls im Winterurlaub im Ausland die gesamte Automatik zerschießt und mir Pflanzen, Heizung und was weiß ich noch alles einfrieren, versuche ich solche Ereignisse zu verstehen und ggf. zu verhindern bzw. entsprechend darauf zu reagieren. Ich hoffe und denke zwar, dass einer der beiden anderen HM-CFG-LAN das noch auffangen würde, allerdings bin ich mit Ideen und damit neuen Geräten noch nicht am Ende.
Ich habe mal ein list von dem Wandthermostaten gemacht. Falls das nicht reicht liefere ich gerne mehr Infos.

Da alles wieder läuft sind also nur die Fragen offen:
Wer war der Schuldige, der Lanadapter oder das Wandthermostat?
Wie bekomme ich eine derartige Situation nur per Zugriff von Außen gelöst?
Besser: wie kann ich ein derartiges Szenario im Ansatz erkennen und automatisch verhindern?

Danke vorab!

Code Auswählen Erweitern

Internals:
   CFGFN      /opt/fhem/FHEM/0_43_OG_Bad.cfg
   DEF        367259
   HMLAN_1_MSGCNT 20656
   HMLAN_1_RAWMSG E367259,0000,48DE843D,FF,FFB4,0D847036725900000000E73F
   HMLAN_1_RSSI -76
   HMLAN_1_TIME 2018-08-27 19:38:59
   HMLAN_2_MSGCNT 19780
   HMLAN_2_RAWMSG E367259,0000,02584ECC,FF,FFB4,0D847036725900000000E73F
   HMLAN_2_RSSI -76
   HMLAN_2_TIME 2018-08-27 19:38:59
   HMLAN_3_MSGCNT 21074
   HMLAN_3_RAWMSG E367259,0000,496E3B37,FF,FFC0,0D847036725900000000E73F
   HMLAN_3_RSSI -64
   HMLAN_3_TIME 2018-08-27 19:38:59
   IODev      HMLAN_3
   LASTInputDev HMLAN_1
   MSGCNT     61510
   NAME       OG_Bad_Thermostat
   NOTIFYDEV  global
   NR         684
   NTFY_ORDER 50-OG_Bad_Thermostat
   STATE      CMDs_done
   TYPE       CUL_HM
   channel_01 OG_Bad_Weather
   channel_02 OG_Bad_Temp
   channel_03 OG_Bad_WindowRec
   channel_06 OG_Bad_remote
   channel_07 OG_Bad_SwitchTr
   lastMsg    No:0D - t:70 s:367259 d:000000 00E73F
   protCmdDel 7
   protLastRcv 2018-08-27 19:38:59
   protRcv    169 last_at:2018-08-27 19:38:59
   protResnd  1 last_at:2018-08-27 19:10:14
   protResndFail 1 last_at:2018-08-27 19:10:19
   protSnd    137 last_at:2018-08-27 19:12:12
   protSndB   3 last_at:2018-08-27 19:11:54
   protState  CMDs_done
   rssi_HMLAN_1 cnt:2 min:-61 max:-61 avg:-61 lst:-61
   rssi_HMLAN_3 cnt:148 min:-56 max:-48 avg:-50.77 lst:-49
   rssi_at_HMLAN_1 cnt:19096 min:-100 max:-70 avg:-74.48 lst:-76
   rssi_at_HMLAN_2 cnt:18305 min:-104 max:-71 avg:-81.35 lst:-76
   rssi_at_HMLAN_3 cnt:19548 min:-88 max:-57 avg:-62.23 lst:-64
   READINGS:
     2018-08-12 11:03:41   Activity        alive
     2018-08-27 19:11:55   CommandAccepted yes
     2017-10-22 19:33:33   D-firmware      1.3
     2017-10-22 19:33:33   D-serialNr      MEQxxxxxx
     2018-08-27 19:11:55   PairedTo        0xA1B6F4
     2016-11-25 18:36:11   R-burstRx       on
     2016-11-25 18:36:11   R-cyclicInfoMsg on
     2016-11-25 18:36:11   R-cyclicInfoMsgDis 0
     2016-11-25 18:36:11   R-pairCentral   0xA1B6F4
     2018-08-27 19:11:55   RegL_00.          01:01 02:01 09:01 0A:A1 0B:B6 0C:F4 0F:00 11:00  12:16 16:00 18:00 19:00 1A:00 00:00
     2018-08-27 19:38:49   battery         ok
     2018-08-27 19:38:49   batteryLevel    2.6
     2018-08-27 19:38:49   desired-temp    17.0
     2018-08-27 19:38:49   measured-temp   23.1
     2018-08-27 19:11:50   powerOn         2018-08-27 19:11:50
     2018-08-27 19:11:50   recentStateType info
     2018-08-04 19:00:04   sabotageAttack_ErrIoAttack cnt 1
     2018-08-26 08:45:07   sabotageAttack_ErrIoAttack cnt 3
     2018-08-27 19:12:12   state           CMDs_done
     2018-08-27 19:11:52   time-request    -
     RegL_07.:
       VAL       
   helper:
     HM_CMDNR   13
     PONtest    1
     cSnd       01A1B6F436725907040000000001,01A1B6F436725907042EB5730107
     mId        00AD
     regLst     ,0
     rxType     6
     supp_Pair_Rep 0
     ack:
     expert:
       def        1
       det        0
       raw        1
       tpl        0
     io:
       newChn     +367259,00,00,00
       nextSend   1535391539.93606
       prefIO     
       rxt        0
       vccu       HMVCCU
       p:
         367259
         00
         00
         00
     mRssi:
       mNo        0D
       io:
         HMLAN_1:
           -76
           -76
         HMLAN_2:
           -76
           -76
         HMLAN_3:
           -60
           -60
     prt:
       awake      0
       bErr       0
       sProc      0
       rspWait:
     q:
       qReqConf   
       qReqStat   
     role:
       dev        1
       prs        1
     rssi:
       HMLAN_1:
         avg        -61
         cnt        2
         lst        -61
         max        -61
         min        -61
       HMLAN_3:
         avg        -50.7770270270271
         cnt        148
         lst        -49
         max        -48
         min        -56
       at_HMLAN_1:
         avg        -74.4835043988269
         cnt        19096
         lst        -76
         max        -70
         min        -100
       at_HMLAN_2:
         avg        -81.357880360557
         cnt        18305
         lst        -76
         max        -71
         min        -104
       at_HMLAN_3:
         avg        -62.2378759975448
         cnt        19548
         lst        -64
         max        -57
         min        -88
     shRegW:
       07         02
     shadowReg:
     tmpl:
Attributes:
   IODev      HMLAN_1
   IOgrp      HMVCCU
   actCycle   000:10
   actStatus  alive
   autoReadReg 5_readMissing
   event-on-change-reading battery,controlMode,desired-temp,dewpoint,humidity,measured-temp
   expert     2_raw
   firmware   1.3
   icon       hm-tc-it-wm-w-eu
   model      HM-TC-IT-WM-W-EU
   msgRepeat  1
   room       OG_Bad
   serialNr   MEQxxxxxx
   subType    thermostat
   webCmd     getConfig:clear msgEvents

[frank]

27000 messages allein sagt noch nicht viel aus, wenn der zeitraum und die "normale" kommunikation unbekannt ist. zb häufiges setzen der templisten.

haben deine hmlan fw 0.965?
"set hmlan restart" hätte das sendekontingent des hmlan wieder maximiert.

ich würde bei allen stationären devices ein prefered io setzen (attr IOgrp vccu:<prefIO>). damit kann man zb die load der hmlan einigermassen gleich verteilen.
mit attr loadLevel beim hmlan kannst du dann zb ein zusätzlichen "warning level" einbauen, den du dann beim reading loadLevel überwachen kannst. somit würdest du bereits frühzeitig alarmiert werden, nicht erst nach dem crash.

ich logge zb die aktuelle load meiner io und sehe im plot sofort, wenn etwas unrund läuft. quasi wie beim arzt ein langzeit EKG.

automatisches "rum-doktorn" kann auch schnell mal nach hinten losgehen.

[alanblack]

Hallo frank,

Danke für Deine Antwort!

27000 messages allein sagt noch nicht viel aus, wenn der zeitraum und die "normale" kommunikation unbekannt ist. zb häufiges setzen der templisten.

Sorry, ich hatte vergessen zu schreiben, dass dies innerhalb von Minuten passiert sein muss. Templisten werden bei dem Thermostat nicht bzw. nicht automatisch geändert.
Es wurden kurz zuvor nur Normal- und Absenktemperatur geändert.

haben deine hmlan fw 0.965?

Ja!

"set hmlan restart" hätte das sendekontingent des hmlan wieder maximiert.

Ja, okay, zum Retten des Systems geht das vielleicht. Hauptsache ist dabei aber, dass Amok-laufende Geräte das nicht gleich wieder aufbrauchen. Daher suche ich auch nach der möglichen Ursache und will nicht nur das Symptom bekämpfen.

ich würde bei allen stationären devices ein prefered io setzen (attr IOgrp vccu:<prefIO>). damit kann man zb die load der hmlan einigermassen gleich verteilen.

Die drei HMLan liegen im Mittel im Bereich von +-1000 Messages/Tag gleich auf. Das sollte auch ohne preferredIO passig genug sein.

mit attr loadLevel beim hmlan kannst du dann zb ein zusätzlichen "warning level" einbauen, den du dann beim reading loadLevel überwachen kannst. somit würdest du bereits frühzeitig alarmiert werden, nicht erst nach dem crash.

Da ich nicht vor Ort war und die Meldungen High- (90%) und Overload (99%) mal gerade 47 Sekunden auseinanderlagen, weiß ich nicht, ob mir eine Warnung bei kA 60% (?) noch genug Zeit verschafft hätte. Werde ich aber mal einbauen. Danke für den Tipp!

ich logge zb die aktuelle load meiner io und sehe im plot sofort, wenn etwas unrund läuft. quasi wie beim arzt ein langzeit EKG.

Ja, aber erst, wenn Du den Plot abrufst. Wenn das so aussieht (beachte 8 Uhr; davon sind laut protoEvent short 27164 an das besagte Thermostat gegangen)

Code Auswählen Erweitern


send        | 00| 01| 02| 03| 04| 05| 06| 07| 08| 09| 10| 11| 12| 13| 14| 15| 16| 17| 18| 19| 20| 21| 22| 23
    HMLAN_3   :| 23| 19| 38| 23| 29|163|109|133|27461|119| 37| 17| 12|  6| 61|234| 67| 60| 87|299|297|142| 75| 36

suche ich nach einer klugen Lösung.

automatisches "rum-doktorn" kann auch schnell mal nach hinten losgehen.

Dass ein "notify HMLan:loadlevel>60 set HMLan restart" oder ähnliches wahrscheinlich irgendwann oder eher wohl ziemlich schnell in die Hose geht, ist mir klar.
Wenn dann wäre etwas wie "notify HMLan_an_DeviceXY:loadlevel>60 attr DeviceXY dummy 1" das Höchste der Gefühle. Aber ich habe noch nicht gefunden, wie ich an die einzelnen Zahlen aus protoEvent komme.

[frank]

entscheidend für overload sind nur die vom jeweiligen io gesendeten. messages. receive messages sind dabei unwichtig. könnte eventuell auch dein nachbar sein, der gesendet hat, denke ich.

zusätzlich kommt es auf die länge der gesendeten messages an. entscheidend ist immer der wert, den der hmlan im internal msgLoadCurrent anzeigt.

mit attr dummy kannst du aber wahrscheinlich nur die von fhem gesendeten messages abschalten. bei manchen messages wird nur der empfang durch ein "ack" quittiert. ist ein device mit einem hmlan assigned, sendet dieser die "ack" von sich aus an "seine" devices. man müsste das device wahrscheinlich zuätzlich unassignen.
vielleicht wäre für solche fälle das attr ignore besser.

in perl müsste man die ausgabe des befehls "get hminfo msgStat" zb einer variablen zuweisen können:

Code Auswählen Erweitern

$my_text = fhem("get hminfo msgStat");

hat eventuell jemand beim thermostat ein knöpfchen gedrückt, welches sich verklemmt und dadurch dauerfeuer ausgelöst hat?

[alanblack]

entscheidend für overload sind nur die vom jeweiligen io gesendeten. messages. receive messages sind dabei unwichtig. könnte eventuell auch dein nachbar sein, der gesendet hat, denke ich.

Ich hatte nichts von empfangenen messages geschrieben. protoEvents short lieferte klar 27164  in der Spalte Snd um ~19 Uhr. Das sind Werte, die ich nicht einmal annähernd mit meinen HM-ES-PMSw1-Pl bis 24 Uhr erreiche.
Nachbarn mit HM-Devices? Fehlanzeige! Meine Nachbarn sind eher > 70a und sprechen mich an, wenn bei deren Billig-DECT-Telefonen die Akkupacks nicht mehr wollen. Es sei denn, dass einer etwas weiter weg sich Yagi-Antennen an seine Devices gebaut hat.

zusätzlich kommt es auf die länge der gesendeten messages an. entscheidend ist immer der wert, den der hmlan im internal msgLoadCurrent anzeigt.

Ja, und wie bringt mich das weiter? Das ist bei mir so 3-7, selten mal über 10. Als ich auf die HMLans nach der Highload-Nachricht geschaut hatte, waren es bei diesem einen 100. Die Frage ist, warum?
Das System läuft eigentlich auch problemlos mit zwei HMLans. Das dritte lief mir für einen schmalen EUR über den Weg und schafft nur Luft für Erweiterungen.

in perl müsste man die ausgabe des befehls "get hminfo msgStat" zb einer variablen zuweisen können:

Code Auswählen Erweitern

$my_text = fhem("get hminfo msgStat");

Das funktioniert auch. Das ist zwar unschön zu parsen, aber wenn es die einzige Quelle ist, nehme ich die.

hat eventuell jemand beim thermostat ein knöpfchen gedrückt, welches sich verklemmt und dadurch dauerfeuer ausgelöst hat?

Keine Personen waren anwesend.

Sorry, aber ich vermute immer noch, dass eher der HM-TC-IT-WM-W-EU ein Problem hatte, weil die Kommunikation vom HMLan zum Thermostat bis zum Entnehmen einer Batterie nicht sauber lief, danach aber schon.

[frank]

Ich hatte nichts von empfangenen messages geschrieben. protoEvents short lieferte klar 27164  in der Spalte Snd um ~19 Uhr. Das sind Werte, die ich nicht einmal annähernd mit meinen HM-ES-PMSw1-Pl bis 24 Uhr erreiche.

ich könnte schwören, dass ich receive im geposteten ausschnitt von msgStat gesehen habe.   

das sind knapp 8 gesendete messages pro sekunde. das ist für eine "normale" kommunikation wahrscheinlich zu viel, da die gegenseite ggf nach ca 100 ms antworten muss.

in fhem.log gibt es nichts während dieser zeit?

Ja, und wie bringt mich das weiter? Das ist bei mir so 3-7, selten mal über 10. Als ich auf die HMLans nach der Highload-Nachricht geschaut hatte, waren es bei diesem einen 100. Die Frage ist, warum?

gegenfrage: was bringt die anzahl der messages für vorteile?

ok, spätestens zum automatischen erkennen des problemdevices müsste man bei jedem device die anzahl der messages checken, da es keine andere möglichkeit gibt.

mit einem 2. test fhem und cul konnte ich mein produktiv fhem (vccu mit hmlan + hmusb) bereits mit einer message pro sekunde komplett lahmlegen. beide io waren vielleicht nach ca 1 std im overload, obwohl sie "nur" gezwungen wurden, mit einem ack zu antworten.

ich vermute weiterhin, dass der tc eine message im dauerfeuer gesendet hat, worauf die hmlan antworten mussten. aber was der auslöser war, keine ahnung.

da hmlans mit alter fw durch homematicIP messages zum permanenten rebooten gebracht werden können, wäre es für mich auch denkbar, dass der tc zufällig eine "wilde" message gehört hat.

auf jeden fall würde ich ihn besonders beobachten.

[alanblack]

ich könnte schwören, dass ich receive im geposteten ausschnitt von msgStat gesehen habe.   

Hast Du auch. Ich hatte aus dem msgStat die beiden Zeilen einzeln in den <code>-Block kopiert und mir war erst nach dem Abschicken irgendwann aufgefallen, dass ich die falsche Kopfzeile erwischt hatte. Wer kopiert, verliert.

in fhem.log gibt es nichts während dieser zeit?

Das einzige, was in der Zeit vor dem Overload ungewöhnliches passiert war, ist, dass durch eine abrauchende Lampe die Sicherung rausgeflogen ist, woran auch eines der beiden anderen HMLan hängt. Das hatte mich gestern Abend dazu verleitet, den Fehler für heute Morgen mit einer "dummen" Zeitschaltuhr nachzustellen, ob der Ausfall eines HMLan die anderen in Schwierigkeiten bringt. Nö, das war es nicht.

gegenfrage: was bringt die anzahl der messages für vorteile?

ok, spätestens zum automatischen erkennen des problemdevices müsste man bei jedem device die anzahl der messages checken, da es keine andere möglichkeit gibt.

Genau das war mein Gedanke.

ich vermute weiterhin, dass der tc eine message im dauerfeuer gesendet hat, worauf die hmlan antworten mussten. aber was der auslöser war, keine ahnung.

Ich hatte nochmal darüber nachgedacht: da fiel mir https://forum.fhem.de/index.php/topic,60472.msg518537.html ein. Das TC von damals mit der leeren Batterie war das selbe wie bei dem Overload vor drei Tagen. Gibt es einen einfachen Weg ein TC mit allen Pairings und Peerings zu ersetzen? Hmmm.... bringt mich aber auch nur dann weiter, wenn der Fehler öfter als alle zwei Jahre aufträte.

[Otto123]

Gibt es einen einfachen Weg ein TC mit allen Pairings und Peerings zu ersetzen?

Hab es noch nie gemacht -> hmInfo kann das eventuell?

x-deviceReplace <oldDevice> <newDevice>
Ersetzen eines alten oder defekten Device. Das neue Ersatzdevice muss kompatibel zum Alten sein - FHEM prüft das nur rudimentär. Der Anwender sollt es sorgsam prüfen.
Das Kommando muss aus Sicherheitsgründen 2-fach ausgeführt werden. Der erste Aufruf wird mit einem CAUTION quittiert. Nach Auslösen den Kommandos ein 2. mal werden die Devices umbenannt und umkonfiguriert. Er werden alle peerings, Register und Templates im neuen Device UND allen peers umgestellt.
ACHTUNG: Nach dem Auslösen kann die Änderung nicht mehr automatisch rückgängig gemacht werden. Manuell ist das natürlich möglich.
Auch ein ückspring auf eine ältere Konfiguration erlaubt KEIN Rückgängigmachen!!!
Sollte das Device und seine Kanäle über Templates definiert sein - also die Registerlisten - kann im Falle von Problemen in der Übertragung - problemlos wieder hergestellt werden.

[frank]

Das TC von damals mit der leeren Batterie war das selbe wie bei dem Overload vor drei Tagen

nachdem das schwören so gut funktioniert hat, wette ich jetzt mal auf einen zusammenhang.   

kann man vielleicht am batlevel verlauf etwas erkennen? sind die batterien noch von damals?

hast du die fw 1.3 installiert, oder ist sie von eq3 aufgespielt. falls du sie so gekauft hast, würde ich die zum download verfügbare fw1.3 drüberflashen.

laut changelog gibt es 2 versionen der fw1.3
https://www.eq-3.de/Downloads/Software/Firmware/changelog_hm_tc_it_wm_w_eu_update_V1_3_002_150827.txt

da die versionsanzeige immer nur die ersten 2 ziffern darstellen kann, könnte theoretisch bei einem mit fw1.3 gekauften tc die ältere version geflasht sein. im changelog gibt es zwar keinen hinweis auf deinen fehler, aber wer weiss...

in 2 jahren weisst du dann mehr. 

[alanblack]

nachdem das schwören so gut funktioniert hat, wette ich jetzt mal auf einen zusammenhang.   

Das kann ich jetzt auch mal unterschreiben. Bezug nehmend auf

Das einzig auffällige war ein HM-TC-IT-WM-W-EU, das nach dem Einlegen der Batterie "low Batt" anzeigte. Ich bin eigentlich sehr sicher, dass das Symbol vorher nicht da war.

passierte folgendes:
- 6 CMDs pending bei dem TC
- Bedienung am TC funktioniert
- KEIN(!) Batteriesymbol
- Batterien raus, ein paar Sekunden warten, diese Batterien wieder rein
...
Meine Frau hat mich für verrückt erklärt. Ich hingegen habe nur nicht wieder aufhören können zu lachen, als ich nach dem "Syn" im Display das Symbol für "Low-Bat" erblickte.

kann man vielleicht am batlevel verlauf etwas erkennen? sind die batterien noch von damals?

Könnte man vielleicht, wenn ich nicht irgendwann mal viele Logs gelöscht hätte. Die Batterien sind diejenigen, welche ich vor knapp zwei Jahren eingelegt hatte.
Also liegt für mich die Vermutung nahe, dass dieser TC mit fast leeren Batterien anfängt, Faxen zu machen.

hast du die fw 1.3 installiert, oder ist sie von eq3 aufgespielt. falls du sie so gekauft hast, würde ich die zum download verfügbare fw1.3 drüberflashen.

laut changelog gibt es 2 versionen der fw1.3
https://www.eq-3.de/Downloads/Software/Firmware/changelog_hm_tc_it_wm_w_eu_update_V1_3_002_150827.txt

Ich habe drei HMLan... Ich halte das Thema Firmwareupdate für eines, welches ich dann verfolgen sollte, wenn es Probleme gibt oder deutliche Verbesserungen zu erwarten sind. Das hat die letzten gut 20 Jahre bei PCs bzw. PC-Komponenten, Unterhaltungselektronik oder Handys gut funktioniert. Vielleicht sollte ich in Anbetracht der Anzahl der Geräte bzw. Gerätetypen im Bereich Hausautomation hier umdenken.

in 2 jahren weisst du dann mehr. 

Ich hoffe, dass ich neue Erkenntnisse in der Sache nicht erst dann haben werde. Jetzt sind erstmal neue Batterien drin. Dann sehe ich zu, dass ich "mein Haus updaten" kann. Am TC in steht in fhem ein Hinweis für den Fall, dass die Batterien das nächste Mal fast leer sind.

Auf jeden Fall habe ich eine Info mehr aus dem Ereignis als vorher:

Hab es noch nie gemacht -> hmInfo kann das eventuell?
[x-deviceReplace <oldDevice> <newDevice>]

Danke dafür!

[alanblack]

laut changelog gibt es 2 versionen der fw1.3
https://www.eq-3.de/Downloads/Software/Firmware/changelog_hm_tc_it_wm_w_eu_update_V1_3_002_150827.txt

Mini-Update: mit dem jetzt vorhandenen HM-MOD-RPI-PCB (siehe https://forum.fhem.de/index.php/topic,90737.0.html) habe ich diese Firmware geflasht. Mal schauen, ob ich irgendwie früher als in zwei Jahren herausfinden kann, ob der Fehler jetzt weg ist.

[frank]

dann aber hoffentlich mit fast leeren batterien bestückt.
und das loggen von batvoltage nicht vergessen.