Ich habe in den letzten Wochen 2 mal das Problem gehabt, dass sich FHEM komplett aufgehangen hat, weil aus einen mir nicht ersichtlichen Grund, das HMUARTLGW erst in den Overload gegangen ist und danach disconnected wurde (soweit so gut). Danach hat das Modul offenbar trotzdem weiter versucht, Daten an das LGW zu senden und dadurch FHEM mit 100% CPU Last lahmgelegt.
Hier ein Log Auszug:
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw: queue is full, dropping packet
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw: queue is full, dropping packet
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw: queue is full, dropping packet
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw: queue is full, dropping packet
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw: queue is full, dropping packet
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw: queue is full, dropping packet
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:40 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:41 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:41 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:41 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:42 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:42 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:42 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:43 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:44 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:45 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:49 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:53 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:50:57 1: HMUARTLGW EG.wz.HmGw:keepAlive KeepAlive sent 6.219s too late, this might cause a disconnect!
2018.10.27 08:51:02 1: 10.0.0.109:2001 disconnected, waiting to reappear (EG.wz.HmGw:keepAlive)
2018.10.27 08:51:02 1: HMUARTLGW EG.wz.HmGw IO in overload!
2018.10.27 08:51:16 1: HMUARTLGW EG.wz.HmGw:keepAlive did not respond after all, reopening
2018.10.27 08:51:17 3: EG.wz.HmGw device closed
2018.10.27 08:51:24 3: Opening EG.wz.HmGw:keepAlive device 10.0.0.109:2001
2018.10.27 08:51:24 1: 10.0.0.109:2000 reappeared (EG.wz.HmGw)
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
..... und so weiter bis zum manuellen Stop/Restart von FHEM.
Warum das Device in den Overload geht, ist mir noch nicht klar. Die Routinen funktionieren eigentlich seit vielen Monaten sehr zuverlässig und das ist jetzt auch erst 2 mal passiert.
Mich würde eher interessieren, warum an dieser Stelle die Initialisierung nicht richtig funktioniert und dann trotzdem Daten gesendet werden, obwohl das Device nicht empfangsbereit ist. Kann man da im Modul eine Fehlerbehandlung einbauen um FHEM dadurch nicht lahmzulegen?
2018.10.27 08:51:24 3: Opening EG.wz.HmGw:keepAlive device 10.0.0.109:2001
2018.10.27 08:51:24 1: 10.0.0.109:2000 reappeared (EG.wz.HmGw)
2018.10.27 08:51:24 1: HMUARTLGW EG.wz.HmGw: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B0010A0B0C54179A00050000000009
Hier wurde ja offenbar das Device nicht korrekt initialisiert, nach dem es wegen dem Overload zum Disconnect kam.
Kann man da was machen?
Nachtrag: Der Overload tritt offenbar manchmal auf, wenn ich für die Heizungsthermostate über HMInfo (templist restore) die Steuerungsprogramme aktualisiere. Soweit ich verstehe, sollte das CUL_HM ja automatisch dafür sorgen, dass es hier nicht zu einem Overload der Queue kommt. Vielleicht kann man auch an der Stelle irgendwo ansetzen?
Zwei solche Baustellen gleichzeitig... :-\
Zum Thema overload:
Prüf mal über HMInfo -> protoEvents short ob Du eingrenzen kannst, was bei Dir soviel Traffic verursacht. Oder Du schickst mal das Ergebnis.
Zum Thema HMUARTLGW:
Mir fielen die verschiedenen Portnummern auf:
2018.10.27 08:51:24 3: Opening EG.wz.HmGw:keepAlive device 10.0.0.109:2001 (<= hier)
2018.10.27 08:51:24 1: 10.0.0.109:2000 (<= und hier) reappeared (EG.wz.HmGw)
Geht das überhaupt? Oder ist da ein define schief?
Das Gateway hat soweit ich weiß ein BidCos Port (2000) und ein KeepAlive Port (2001). Daher die unterschiedlichen Angaben.
Nach dem ProtoEvents muss ich mal gucken, aber nach dem Restart dürfte da jetzt wohl nichts aufregendes zu sehen sein. Da das Problem jetzt in den letzten 2-3 Monaten nur 2 mal aufgetreten ist, muss ich das wohl mal weiter beobachten.
Zitat von: Phiolin am 27 Oktober 2018, 21:20:55
Das Gateway hat soweit ich weiß ein BidCos Port (2000) und ein KeepAlive Port (2001). Daher die unterschiedlichen Angaben.
Da ist dann wohl kein Problem begründet.
Zitat
Nach dem ProtoEvents muss ich mal gucken, aber nach dem Restart dürfte da jetzt wohl nichts aufregendes zu sehen sein. Da das Problem jetzt in den letzten 2-3 Monaten nur 2 mal aufgetreten ist, muss ich das wohl mal weiter beobachten.
Ok, könnte eine Geschichte sein wie in https://forum.fhem.de/index.php/topic,90618.msg831794.htm (https://forum.fhem.de/index.php/topic,90618.msg831794.htm). Seit dem schreiben meine HM-IO beim Überschreiten von loadLevel von 40 ein fhem("get HMInfo protoEvents short") ins Log - abgesehen vom wieder aktivierten Logging von battery etc. ;)
Zitat
Nachtrag: Der Overload tritt offenbar manchmal auf, wenn ich für die Heizungsthermostate über HMInfo (templist restore) die Steuerungsprogramme aktualisiere. Soweit ich verstehe, sollte das CUL_HM ja automatisch dafür sorgen, dass es hier nicht zu einem Overload der Queue kommt. Vielleicht kann man auch an der Stelle irgendwo ansetzen?
Den Nachtrag hatte ich beim letzten Schreiben nicht gesehen. Wie viele TC hast Du am laufen?
Ich nutze aus verschiedenen Gründen die templists nicht. Meine Routinen prüfen den loadLevel aller IO jetzt vor jedem "Raum-Update".
Nur ein Wand- und ein Heizkörper Thermostat. Also nicht wirklich viele.😊
Aber ich baue mir auch mal was zum loggen bei hoher Load ein, mal gucken, wann es das nächste mal Auftritt.