HMUARTLGW queue full und Device not initialized but asked to send data

gritob · 03 Dezember 2018, 11:11:01

Hallo,

ich habe hier ein sehr schwerwiegendes Problem mit einer FHEM-Installation. Zum Aufbau: ich habe eine größere Anzahl an Thermostaten und Wandthermostaten, welche mittels VCCU und einer Reihe von angeschlossenen HMUARTLGWs angesprochen werden. Das ganze beschriebene Problem tritt erst auf, nachdem die Wandthermostate installiert wurden. Nach gut 30-60 Minuten reagiert FHEM nicht mehr und lässt sich weder per telnet, noch per webinterface ansprechen. In den Logs konnte ich dann sehen, dass wohl die queue einiger meiner HMUARTLGWs vollgelaufen ist und ich folgende Nachricht bekomme:

HMUARTLGW 4001_PEQ0531825: queue is full, dropping packet

Die Nachricht wird mehr oder weniger gespammt, ist aber kein Vergleich zu dem was kurz darauf folgt:

HMUARTLGW 4001_PEQ0531825: Device not initialized (state: 3, init) but asked to send data. Dropping: As1001B00145FF965C174700050000000000

Die Nachricht wird kurz daraufhin mehrere hundert mal pro Sekunde erzeugt und knallt meine Logs nur so zu. Dann reagiert auch FHEM nicht mehr und ich habe nur die Möglichkeit den Prozess zu killen und FHEM neu zu starten. Der beschriebene HMUARTLGW ist hier aber nur ein Beispiel, genauso wie die Nachricht und der state (der ist manchmal auch glaube ich state:2 disconnected). Es tritt auch mit anderen HMUARTLGWs auf. Wichtig ist vielleicht noch, dass dies im Ruhemodus passiert, also ich setze nicht wild irgendwelche Temperaturen oder ähnliches.

Was ich jetzt schon gemacht habe:

alle HMUARTLGWs auf FW 1.4.1 upgedated
autoReadReg der Wandthermostate auf off gestellt, um die Last beim Starten niedrig zu halten
qLen testweise auf 60 und aktuell auf 200 gesetzt
noch mehr HMUARTLGWs aufgestellt
FHEM auf aktuelle Version upgedated

Das alles hat nur bewirkt, dass ich den Absturz etwas hinauszögere aber leider nicht unterbinden kann. Ich habe die Vermutung, dass es mit den Wandthermostaten zusammenhängt, da ich auch Installationen besitze, welche ähnlich groß sind aber anstatt Wandthermostate eben normale Thermostate haben und das dort dann nicht auftritt. Die Last eines einzelnen HMUARTLGWs geht kaum über 10% und es tritt trotzdem auf. Meine Fragen wären jetzt:

Kann ich noch bestimmte Einstellungen in den Wandthermostaten vornehmen, die ich nicht bedacht habe? Die Wandthermostate sind (noch) nicht mit den Thermostaten gepeert
Kann ich die Größe der aktuellen Queue irgendwie auslesen, damit ich den HMUARTLGW einfach erstmal neustarten kann, damit FHEM zumindest weiterläuft?
Was kann ich sonst quasi noch tun?

Grüße und Danke

frank · 03 Dezember 2018, 11:56:34

wenn du bei allen devices autoreadreg=0 setzt und keine befehle an die devices sendest, sollte eigentliche ruhe sein.

hat dein system eventuell ein speicherproblem?
gibt es zb "cannot fork" meldungen im fhem.log?
gibt es freezes in fhem? => modul freezemon
was sagt "get hminfo configCheck"?

mit "attr dummy 1" im hauptdevice sollten solche devices in fhem eigentlich komplett stillgelegt werden können. durch entfernen der attribute könntest du dann nach und nach devices wieder "freigeben" und beobachten wo genau das problem liegt.

haben die WT aktuelle fw?
gibt es nachbarn mit homematic, eventuell sogar mit hmip? siehe zb die "unknown device" readings in der vccu.

gritob · 03 Dezember 2018, 14:19:04

Speicherproblem kann ich eigentlich ausschließen. Habe wie gesagt einige ähnliche Instanzen und es tritt nur bei vielen Wandthermostaten auf. Teilweise habe ich viel mehr Geräte im Einsatz und es passiert nichts.

Ich habe die logs mal gefiltert nach fork und habe keine Ergebnisse bekommen.

Freezemon hatte ich nicht aktiviert und läuft jetzt, ich werde berichten, wenn sich dort was tut!

Der configcheck wirft viele Geräte raus, wo er noch einige Register nicht lesen konnte und das peering nicht aktiv ist. Ist das sehr problematisch? Ich habe das Auslesen der Register ja erstmal auf off gestellt und vorher ist er mir ja immer abgestürzt, bevor er alles einlesen konnte.

Das mit attr dummy 1 werde ich mir mal merken und mal mit rumspielen. Danke für den Tipp.

Die fw auf den Geräten ist 1.3. Eine neuere gibt es nicht oder? Ansonsten gibt es bei unknown devices schon so 10-15 Stück, das könnten aber noch Austauschgeräte aus der Installation sein. Spielt der Funkverkehr der unbekannten Geräte eine große Rolle? Wenn ja, kann ich ihn irgendwie blockieren? Danke schon mal für die Antwort

mgernoth · 04 Dezember 2018, 20:16:21

Hallo,

Zitat von: gritob am 03 Dezember 2018, 11:11:01
HMUARTLGW 4001_PEQ0531825: Device not initialized (state: 3, init) but asked to send data. Dropping: As1001B00145FF965C174700050000000000

Was ist 5C1747? Diese Konfigurationsmessage für dieses Geräts löst das Problem aus.

Was hier passiert ist, dass CUL_HM in einer Endlosschleife diese Message sendet. Die Meldungen von HMUARTLGW sind nur Symptom, nicht Ursache. Ich hatte das auch einmal bisher, konnte es aber nicht reproduzieren und damit auch nicht debuggen...

Kannst Du bitte mal ein List von 5C1747 posten?

Viele Grüße
Michael

XXL-Wing · 08 Dezember 2018, 12:55:54

Hallo,

ich hab ein gleichgelagertes Problem. Memory oder sonstige Resourcenknappheit am Rechner mit fhem sind ausgeschlossen, allerdings benötigt fhem in dem Zustand dann extrem viel CPU und RAM. Sobald man FHEM beendet/neustartet ist wieder Ruhe für einige Zeit. Das Verhalten kommt aber alle 2-3 Tage wieder.

Bei mir ist es folgende Logzeile:

Code Auswählen


2018.12.08 12:48:23 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B001F100004BD52401050000000001

Im Fehlerfall ca. 150 mal pro Sekunde.

Hier das gewünschte List des Devices:

Code Auswählen


   DEF        4BD524
   IODev      VCCU
   NAME       HM_4BD524
   NOTIFYDEV  global
   NR         151
   NTFY_ORDER 50-HM_4BD524
   STATE      CMDs_done
   TYPE       CUL_HM
   channel_01 HM_4BD524_Btn_01
   channel_02 HM_4BD524_Btn_02
   channel_03 HM_4BD524_Dis
   channel_04 HM_4BD524_Key_01
   channel_05 HM_4BD524_Key_02
   channel_06 HM_4BD524_Key_03
   channel_07 HM_4BD524_Key_04
   channel_08 HM_4BD524_Key_05
   READINGS:
     2018-12-08 08:32:22   CommandAccepted yes
     2018-09-23 18:12:50   D-firmware      1.2
     2018-09-23 18:12:50   D-serialNr      NEQ0711879
     2018-12-08 08:26:34   PairedTo        0xDEAD11
     2016-10-05 04:56:52   R-pairCentral   0xDEAD11
     2016-10-05 04:56:52   R-powerSupply   bat
     2018-12-08 08:26:34   RegL_00.        00:00 02:01 05:80 08:01 0A:DE 0B:AD 0C:11 14:03 21:FF
     2018-11-29 18:00:04   aesCommToDev    pending
     2018-12-08 08:00:08   aesKeyNbr       00
     2018-10-05 20:28:48   battery         ok
     2018-09-23 12:29:42   fwUpdate        done
     2018-12-08 08:15:08   powerOn         2018-12-08 08:15:08
     2018-11-30 17:23:14   sabotageAttackId_ErrIoId_F10000 cnt:18
     2018-12-08 04:20:20   sabotageAttack_ErrIoAttack cnt 44
     2018-12-08 08:32:22   state           CMDs_done
   helper:
     HM_CMDNR   150
     mId        00FB
     regLst     ,0
     rxType     6
     expert:
       def        1
       det        0
       raw        1
       tpl        0
     io:
       newChn     +4BD524,00,00,00
       rxt        0
       vccu       VCCU
       p:
         4BD524
         00
         00
         00
       prefIO:
         HMLanGW
     mRssi:
       mNo        
     prt:
       bErr       0
       sProc      0
     q:
       qReqConf   
       qReqStat   
     role:
       dev        1
     tmpl:
Attributes:
   IODev      VCCU
   IOgrp      VCCU:HMLanGW
   alias      DisplayGarage
   autoReadReg 4_reqStatus
   expert     2_raw
   firmware   1.2
   model      HM-Dis-EP-WM55
   msgRepeat  5
   room       CUL_HM
   serialNr   NEQ0711879
   subType    display
   webCmd     getConfig:clear msgEvents

Das Gerät funktioniert grundsätzlich, nur eben alle 2-3 Tage reisst es den FHEM nieder.

LG
Mike

frank · 08 Dezember 2018, 13:47:57

ich vermute folgendes attribut macht probleme, denn da muss ein echtes io drin stehen. also mal ändern.

Code Auswählen

IODev VCCU

edit:
ausserdem gibt es bei dir ein problem mit der zentrale und/oder den io's.

gepairt ist mit 0xDEAD11 die fehlermeldung kommt aber von 0xF10000. diese "falsche" zentrale erzeugt auch die sabottage readings.

hast du das list manipuliert?
nutzt du eventuell noch einen cul, der nicht in der vccu ist?
zeig mal ein list der vccu.

XXL-Wing · 08 Dezember 2018, 15:48:58

Hi,

ich hab' das IODev mal geändert, mal sehen ob es das verbessert, danke für den Hinweis.
Nein, der Output ist nicht manipuliert, der ist 1:1 reinkopiert.

Ich nutze keinen CUL, ich nutze ein eQ3-HM-LGW und einen HM-CFG-LAN.

Hier das list der VCCU:

Code Auswählen


Internals:
   DEF        DEAD11
   HMLANWZ_MSGCNT 825
   HMLANWZ_RAWMSG EDEAD11,0000,000DA09A,FF,FFB8,3D8002DEAD114C201A00
   HMLANWZ_RSSI -72
   HMLANWZ_TIME 2018-12-08 15:44:28
   HMLanGW_MSGCNT 216
   HMLanGW_RAWMSG 05000044688002DEAD114F24C001012300
   HMLanGW_RSSI -68
   HMLanGW_TIME 2018-12-08 15:46:35
   IODev      HMLanGW
   LASTInputDev HMLanGW
   MSGCNT     1041
   NAME       VCCU
   NOTIFYDEV  global
   NR         16
   NTFY_ORDER 50-VCCU
   STATE      HMLanGW:ok,HMLANWZ:ok,
   TYPE       CUL_HM
   assignedIOs HMLANWZ,HMLanGW
   channel_01 VCCU_Btn1
   lastMsg    No:68 - t:02 s:DEAD11 d:4F24C0 01012300
   protLastRcv 2018-12-08 15:46:35
   protRcv    603 last_at:2018-12-08 15:46:35
   protRcvB   69 last_at:2018-12-08 15:36:47
   rssi_at_HMLANWZ cnt:801 min:-75 max:-58 avg:-64.73 lst:-72 
   rssi_at_HMLanGW cnt:216 min:-79 max:-56 avg:-62.25 lst:-68 
   READINGS:
     2018-12-08 15:46:34   CommandAccepted yes
     2018-12-08 15:43:09   aesKeyNbr       00
     2018-10-27 11:00:08   aesReqTo        HM_4BD524
     2018-12-08 15:43:53   state           HMLanGW:ok,HMLANWZ:ok,
     2016-10-28 13:12:20   unknown_36D02F  received
     2017-10-21 10:05:31   unknown_4553A5  received
     2016-10-28 12:37:40   unknown_4553A6  received
     2016-10-28 12:50:17   unknown_4553B4  received
     2018-09-23 11:10:23   unknown_4BD517  received
     2016-10-31 11:21:08   unknown_4C201A  received
     2016-10-31 11:30:40   unknown_4C2079  received
     2017-01-01 11:32:04   unknown_4C48C5  received
     2017-08-23 08:06:37   unknown_4D118D  received
     2017-08-18 06:28:58   unknown_4DEA30  received
     2017-08-18 14:39:10   unknown_4DEB5D  received
     2017-08-18 14:10:56   unknown_4DEB66  received
     2017-08-18 06:52:25   unknown_4DEB7B  received
     2017-06-09 17:19:07   unknown_4E9AA9  received
     2017-09-26 19:37:41   unknown_4F24C0  received
     2017-09-26 19:44:38   unknown_4F24CA  received
     2017-11-01 09:25:45   unknown_4F9D7E  received
     2018-12-08 15:01:53   unknown_504C9B  received
     2018-01-04 13:17:37   unknown_5152D7  received
     2017-06-03 09:08:25   unknown_5196AB  received
     2017-10-14 12:14:43   unknown_54BB05  received
     2017-10-14 12:14:32   unknown_54BCAF  received
     2018-02-16 10:50:21   unknown_562E6B  received
     2017-08-27 10:49:06   unknown_587FEE  received
     2017-08-27 10:28:43   unknown_58801D  received
     2017-11-01 09:42:24   unknown_5AE7AF  received
     2018-09-14 17:40:17   unknown_5AEEAD  received
     2018-12-08 15:41:14   unknown_788A4E  received
     2017-03-05 11:57:05   unknown_7AA942  received
     2017-10-08 17:12:01   unknown_999999  received
     2018-11-19 05:58:03   unknown_9D6BB1  received
     2018-12-06 00:53:27   unknown_B879F9  received
     2018-08-26 19:34:26   unknown_BC24D5  received
     2018-12-08 12:59:04   unknown_F10000  received
   helper:
     HM_CMDNR   104
     PONtest    1
     mId        FFF0
     regLst     ,0
     rxType     1
     supp_Pair_Rep 0
     ack:
     expert:
       def        1
       det        0
       raw        1
       tpl        0
     io:
       nextSend   1544280395.33602
       prefIO     
       vccu       VCCU
       ioList:
         HMLanGW
         HMLANWZ
     mRssi:
       mNo        68
       io:
         HMLANWZ:
           -72
         HMLanGW:
           -64
           -64
     prt:
       bErr       0
       sProc      0
       rspWait:
     q:
       qReqConf   
       qReqStat   
     role:
       dev        1
       vrt        1
     rssi:
       at_HMLANWZ:
         avg        -64.7328339575532
         cnt        801
         lst        -72
         max        -58
         min        -75
       at_HMLanGW:
         avg        -62.2546296296296
         cnt        216
         lst        -68
         max        -56
         min        -79
     shadowReg:
Attributes:
   IODev      HMLanGW
   IOList     HMLanGW,HMLANWZ
   IOgrp      VCCU
   expert     2_raw
   group      Interfaces
   icon       it_wifi
   model      CCU-FHEM
   room       System
   subType    virtual
   webCmd     virtual:update

mgernoth · 09 Dezember 2018, 01:11:19

Hi,

Zitat von: XXL-Wing am 08 Dezember 2018, 12:55:54
Code Auswählen Erweitern
2018.12.08 12:48:23 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B001F100004BD52401050000000001

Auch eine Configuration-Message, interessant.

Zitat
Hier das gewünschte List des Devices:

Hmm, bis auf das schon angemerkte IODev leider nichts aussergewöhnliches.

Ich hätte eine große Bitte:

Kannst Du bitte in 00_HMUARTLGW.pm nach der Meldung ein stacktrace(); einfügen? Also so (Zeile 1577):

Code Auswählen


Index: FHEM/00_HMUARTLGW.pm
===================================================================
--- FHEM/00_HMUARTLGW.pm	(revision 17923)
+++ FHEM/00_HMUARTLGW.pm	(working copy)
@@ -1574,6 +1574,7 @@
 		    !defined($hash->{Helper}{FW})) {
 			Log3($hash, 1, "HMUARTLGW ${name}: Device not initialized (state: $hash->{DevState}, " .
 			               ReadingsVal($name, "cond", "").") but asked to send data. Dropping: ${msg}");
+			stacktrace();
 			return;
 		}

Dann kriegst Du zwar zusätzlich viele Stacktraces ins Logfile, aber hoffentlich bringen die Erleuchtung.

Danke & Viele Grüße
Michael

XXL-Wing · 09 Dezember 2018, 15:45:24

Hi,

ist eingebaut.
Nach Murphy's Law wird jetzt nix mehr passieren

Ich melde mich wenn es da was "sehbares" gibt.
Vielen Dank schon mal für die Unterstützung!

lG
Mike

XXL-Wing · 09 Dezember 2018, 16:09:42

Kein Murphy, kam ja recht fix, hier die relevanten Log-Teile:

Code Auswählen


2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A778002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.09 15:45:53 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1:     main::CUL_HM_SndCmd                 called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1:     main::CUL_HM_Parse                  called by fhem.pl (3799)
2018.12.09 15:45:53 1:     main::Dispatch                      called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1:     main::HMLAN_Parse                   called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1:     main::HMLAN_Read                    called by fhem.pl (3603)
2018.12.09 15:45:53 1:     main::CallFn                        called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A788002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.09 15:45:53 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1:     main::CUL_HM_SndCmd                 called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1:     main::CUL_HM_Parse                  called by fhem.pl (3799)
2018.12.09 15:45:53 1:     main::Dispatch                      called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1:     main::HMLAN_Parse                   called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1:     main::HMLAN_Read                    called by fhem.pl (3603)
2018.12.09 15:45:53 1:     main::CallFn                        called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A798002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.09 15:45:53 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1:     main::CUL_HM_SndCmd                 called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1:     main::CUL_HM_Parse                  called by fhem.pl (3799)
2018.12.09 15:45:53 1:     main::Dispatch                      called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1:     main::HMLAN_Parse                   called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1:     main::HMLAN_Read                    called by fhem.pl (3603)
2018.12.09 15:45:53 1:     main::CallFn                        called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A7A8002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.09 15:45:53 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1:     main::CUL_HM_SndCmd                 called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1:     main::CUL_HM_Parse                  called by fhem.pl (3799)
2018.12.09 15:45:53 1:     main::Dispatch                      called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1:     main::HMLAN_Parse                   called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1:     main::HMLAN_Read                    called by fhem.pl (3603)
2018.12.09 15:45:53 1:     main::CallFn                        called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A7B8002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.09 15:45:53 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1:     main::CUL_HM_SndCmd                 called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1:     main::CUL_HM_Parse                  called by fhem.pl (3799)
2018.12.09 15:45:53 1:     main::Dispatch                      called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1:     main::HMLAN_Parse                   called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1:     main::HMLAN_Read                    called by fhem.pl (3603)
2018.12.09 15:45:53 1:     main::CallFn                        called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A7C8002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.09 15:45:53 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1:     main::CUL_HM_SndCmd                 called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1:     main::CUL_HM_Parse                  called by fhem.pl (3799)
2018.12.09 15:45:53 1:     main::Dispatch                      called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1:     main::HMLAN_Parse                   called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1:     main::HMLAN_Read                    called by fhem.pl (3603)
2018.12.09 15:45:53 1:     main::CallFn                        called by fhem.pl (726)
2018.12.09 15:45:53 1: HMLAN_Parse: HMLANWZ new condition ok

mgernoth · 09 Dezember 2018, 17:07:30

Hi,

Zitat von: XXL-Wing am 09 Dezember 2018, 16:09:42
Code Auswählen Erweitern
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A778002DEAD1137B07600 2018.12.09 15:45:53 1: stacktrace: 2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000) 2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025) 2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967) 2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799) 2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779) 2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604) 2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603) 2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)

Interessant, hier wird das Problem durch ein Paket ausgelöstet, welches von dem HM-CFG-LAN empfangen wurde. Also scheint es unabhängig vom empfangenden IO zu sein (der Threadersteller hat wohl nur HMUARTs und ich habe das auch einmal auf meinem HMUART Dev-System gesehen).

Die while-Schleife in Zeile 2967 in 10_CUL_HM.pm ist die einzige Stelle, die mir jetzt als evtl. Auslöser auffällt, auch wenn ich mir gerade nicht erklären kann, wie die nicht abbricht und immer wieder die gleiche Nachricht sendet.

Schuss ins Blaue:

Code Auswählen


Index: FHEM/10_CUL_HM.pm
===================================================================
--- FHEM/10_CUL_HM.pm   (revision 17923)
+++ FHEM/10_CUL_HM.pm   (working copy)
@@ -2965,7 +2965,7 @@
                               .($mh{devH}->{helper}{aesAuthBytes}
                                        ?$mh{devH}->{helper}{aesAuthBytes}
                                        :"")
-                  )while ($i<@ack);
+                  )while ($i<int(@ack));
     $respRemoved = $rr;
     Log3 $mh{devN},5,"CUL_HM $mh{devN} sent ACK:".(int(@ack));
     delete($mh{devH}->{helper}{aesAuthBytes});

@Martin: Hast Du irgendeine Idee, warum hier anscheinend CUL_HM in einer Endlosschleife versucht eine Nachricht abzusenden (es kann natürlich auch immernoch ein Fehler in HMUARTLGW sein, auch wenn ich da in dem entsprechenden Codepfad keine Schleife sehe, die das auslösen könnte)?

Viele Grüße
Michael

XXL-Wing · 09 Dezember 2018, 18:55:24

Hi,

Habe den Code mal übernommen.
In der ersten halben Stunde nichts mehr im Log. Ich melde mich wieder wenn es Neuigkeiten gibt.

LG
Mike

noansi · 09 Dezember 2018, 18:58:37

Hallo Michael,

wäre es nicht auch noch interessant, zusätzlich zum Stacktrace auch noch verbose auf 5 für das IO hoch zu setzen?

CUL_HM_SndCmd schreibt nur ans IO. In Endlosschleife wundert mich dann erst mal die komplette Wiederholung des Ablaufs mit Read.
Wäre auch möglich, dass etwas beim Lesen im Empfangspuffer hängen bleibt und immer wieder "empfangen" wird.

Mit verbose = 5 würde das sichtbar werden.

Gruß, Ansgar.

mgernoth · 09 Dezember 2018, 19:50:59

Hallo Ansgar,

Zitat von: noansi am 09 Dezember 2018, 18:58:37
wäre es nicht auch noch interessant, zusätzlich zum Stacktrace auch noch verbose auf 5 für das IO hoch zu setzen?

Ja.

Zitat
In Endlosschleife wundert mich dann erst mal die komplette Wiederholung des Ablaufs mit Read.

Aeh, wieso? Wenn es mitten im Stacktrace eine Endlosschleife gibt, dann sieht alles vor der Schleife immer gleich aus.

Zitat
Wäre auch möglich, dass etwas beim Lesen im Empfangspuffer hängen bleibt und immer wieder "empfangen" wird.

Ja, aber das müsste dann ein Bug sowohl in HMUARTLGW als auch in HMLAN sein, und bei beiden sieht der entsprechende Code korrekt aus. Beide Module benutzen DevIO.pm, aber auch das sieht auf dem entsprechenden Pfad sauber aus.

Zitat
Mit verbose = 5 würde das sichtbar werden.

Ja, mehr debug-Messages wären auf jeden Fall nicht schlecht.

Viele Grüße
Michael

noansi · 09 Dezember 2018, 22:04:14

Hallo Michael,

ZitatAeh, wieso? Wenn es mitten im Stacktrace eine Endlosschleife gibt, dann sieht alles vor der Schleife immer gleich aus.

Oh, danke für den Hinweis. Ich habe stacktrace noch nie genutzt.

ZitatJa, aber das müsste dann ein Bug sowohl in HMUARTLGW als auch in HMLAN sein, und bei beiden sieht der entsprechende Code korrekt aus. Beide Module benutzen DevIO.pm, aber auch das sieht auf dem entsprechenden Pfad sauber aus.

Mir ist da auch kein Fehler aufgefallen.

Code Auswählen

stacktrace(); $attr{$name}{"verbose"}=5;
Wäre mein Änderungsvorschlag, um das Log vor dem ersten stacktrace nicht voll zu müllen, aber mehr Output zu generieren.

Dein Änderungsvorschlag zur u.U. tückischen Abfrage von @ack kann durchaus schon die Lösung sein.

Gruß, Ansgar.