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

[gritob]

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]

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]

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]

Hallo,

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]

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 Erweitern


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 Erweitern


   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]

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

Code Auswählen Erweitern

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]

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 Erweitern


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]

Hi,

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.

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 Erweitern


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]

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]

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

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)
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]

Hi,

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 Erweitern


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]

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]

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]

Hallo Ansgar,

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

Ja.

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.

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.

Mit verbose = 5 würde das sichtbar werden.

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

Viele Grüße
  Michael

[noansi]

Hallo Michael,

Aeh, 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.

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.

Mir ist da auch kein Fehler aufgefallen.

Code Auswählen Erweitern

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.

[XXL-Wing]

Servus,

danke für die vielen Rückmeldungen
Ich habe die Erhöhung des verbose Levels nach dem stacktrace Aufruf eingefügt.

Seit der vorgeschlagenen Änderung mit dem @ack ist kein stacktrace mehr aufgetreten.
Soweit zur guten Nachricht.
Die schlechte ist dass seither das LAN CFG Modul öfter in kurzen Abständen offline geht, sich dann wieder für ein paar Stunden fängt. Kann Zufall sein aber die Häufigkeit entspricht etwa der Anzahl der stacktraces....

Code Auswählen Erweitern


2018.12.10 16:48:57 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:48:57 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:48:57 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:48:58 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:48:58 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:48:58 1: HMLAN_Parse: HMLANWZ new condition ok
2018.12.10 16:49:48 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:49:48 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:49:48 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:49:48 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:49:48 1: HMLAN_Parse: HMLANWZ new condition ok
2018.12.10 16:50:13 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:50:13 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:50:13 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:50:13 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:50:13 1: HMLAN_Parse: HMLANWZ new condition ok
2018.12.10 16:52:17 3: UWZ Unwetterzentrale: Run.1219 Done fetching data
2018.12.10 16:58:08 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:58:08 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:58:08 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:58:08 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:58:08 1: HMLAN_Parse: HMLANWZ new condition ok


lG
Mike

[frank]

hat der hmlan fw0.965?

[gritob]

Hier ist ja einiges passiert wieder

Ich konnte mein Problem zwar nicht nicht lösen aber zumindest tritt es nicht mehr alle halbe Stunde bis Stunde auf sondern nur noch einzeln verteilt über den Tag. Hat es vielleicht doch was damit zu tun, dass sich die Thermostate immer mehr Konfigurationen gezogen haben? Ich werde aber mal die entsprechenden Zeilen Code ändern und dann mal weiter Info hier preisgeben, vielleicht wurde die Lösung ja schon gepostet.

[gritob]

Hallo,

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

sorry ganz übersehen. hier das list:

Code Auswählen Erweitern

Internals:
   DEF        5C1747
   IODev      3051_PEQ0174459
   NAME       HM_5C1747
   NOTIFYDEV  global
   NR         2549
   NTFY_ORDER 50-HM_5C1747
   STATE      CMDs_pending
   TYPE       CUL_HM
   channel_01 HM_5C1747_Weather
   channel_02 HM_5C1747_Climate
   channel_03 HM_5C1747_WindowRec
   channel_06 HM_5C1747_remote
   channel_07 HM_5C1747_SwitchTr
   READINGS:
     2018-12-11 10:57:53   Activity        unknown
     2018-12-03 18:13:13   CommandAccepted yes
     2018-11-15 17:28:53   D-firmware      1.3
     2018-11-15 17:28:53   D-serialNr      OEQ0849210
     2018-11-23 13:22:14   PairedTo        0x45FF96
     2018-11-23 13:22:14   R-burstRx       on
     2018-11-23 13:22:14   R-cyclicInfoMsg on
     2018-11-23 13:22:14   R-cyclicInfoMsgDis 0
     2018-11-23 13:22:14   R-pairCentral   0x45FF96
     2018-11-23 13:22:14   RegL_00.        01:01 02:01 09:01 0A:45 0B:FF 0C:96 0F:00 11:00  12:16 16:00 18:00 19:00 1A:00
     2018-11-23 14:18:45   RegL_07.       
     2018-12-11 01:30:40   battery         ok
     2018-12-11 01:30:40   batteryLevel    2.9
     2018-12-11 01:30:40   desired-temp    21.0
     2018-12-11 01:30:40   measured-temp   20.4
     2018-12-03 18:28:34   state           CMDs_pending
   helper:
     HM_CMDNR   221
     mId        00AD
     regLst     ,0
     rxType     6
     expert:
       def        1
       det        0
       raw        1
       tpl        0
     io:
       newChn     +5C1747,00,00,00
       prefIO     
       rxt        0
       vccu       VCCU0
       p:
         5C1747
         00
         00
         00
     mRssi:
       mNo       
     prt:
       bErr       0
       sProc      0
     q:
       qReqConf   00
       qReqStat   
     role:
       dev        1
       prs        1
     shRegW:
       07         02
     tmpl:
Attributes:
   IODev      3051_PEQ0174459
   IOgrp      VCCU0
   actCycle   000:10
   actStatus  unknown
   autoReadReg 5_readMissing
   expert     2_raw
   firmware   1.3
   model      HM-TC-IT-WM-W-EU
   msgRepeat  1
   room       CUL_HM
   serialNr   OEQ0849210
   subType    thermostat
   webCmd     getConfig:clear msgEvents

[gritob]

Vor einer Stunde ist es wieder passiert. Hier mal mit der Änderung am Code:

Code Auswählen Erweitern

2018.12.12 08:45:01 5: HMUARTLGW 4160_PEQ0533574 HMUARTLGW_Write: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: HMUARTLGW 4160_PEQ0533574: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: stacktrace:
2018.12.12 08:45:01 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.12 08:45:01 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.12 08:45:01 1:     main::CUL_HM_respPendTout           called by fhem.pl (3146)
2018.12.12 08:45:01 1:     main::HandleTimeout                 called by fhem.pl (649)


[mgernoth]

Hi,

Vor einer Stunde ist es wieder passiert. Hier mal mit der Änderung am Code:

Code Auswählen Erweitern

2018.12.12 08:45:01 5: HMUARTLGW 4160_PEQ0533574 HMUARTLGW_Write: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: HMUARTLGW 4160_PEQ0533574: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: stacktrace:
2018.12.12 08:45:01 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.12 08:45:01 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.12 08:45:01 1:     main::CUL_HM_respPendTout           called by fhem.pl (3146)
2018.12.12 08:45:01 1:     main::HandleTimeout                 called by fhem.pl (649)


Vielen Dank, dieser Backtrace sieht eher so aus, wie ich er erwartet hätte. Irgendwo wird ein Resend ständig wiederholt und führt zu dem Problem. "Eigentlich" dürfte das gar nicht passieren können...

Auf Anhieb sehe ich nichts falsches an dem Code, da gibts aber eine Menge Pfade, die zu diesem Zustand führen können...

Woher kommt die Uhrzeit des Systems? Gibt es hier evtl. sync-Vorgänge direkt vor dem Auftreten des Problems, welche das evtl. verursachen könnten?

EDIT: Wenn ich jetzt mal den vorherigen Backtrace ausser acht lasse (evtl. weil er indirekt ausgeloest wurde), dann sind die drei anderen in diesem Thread gemeldeten Pakete Configuration-Pakete an Burst-Devices und auch noch die erste Nachricht an das jeweilige Gerät(As xx 01 B0). Das sieht mir schon sehr nach einer Gemeinsamkeit aus und nicht nach Zufall:

Code Auswählen Erweitern


As1001B00145FF965C174700050000000000
As1001B001F100004BD52401050000000001
As1001B00145FF965B676F00050000000000


@gritob: 5B676F ist auch ein WT? Kannst Du mal bei allen WT autoReadReg auf 4 runtersetzen?

Viele Grüße
  Michael

[gritob]

5B676F ist auch ein WT korrekt! Habe mal autoReadReg für alle WT auf 4 geändert. Uhrzeit ist ne gute Frage. Bei mir läuft FHEM in einem Ubuntu 16.04.2 LTS in einer ESXI VM. Sind mit Sicherheit die Standard Zeitserver angeben, wie oft da ein sync passiert kann ich da aber nicht sagen.

Hier nochmal von heute morgen:

Code Auswählen Erweitern

2018.12.13 07:55:01 5: HMUARTLGW 4151_PEQ0533636 HMUARTLGW_Write: As1001B00145FF965B124B00050000000000
2018.12.13 07:55:01 1: HMUARTLGW 4151_PEQ0533636: Device not initialized (state: 2, init) but asked to send data. Dropping: As1001B00145FF965B124B00050000000000
2018.12.13 07:55:01 1: stacktrace:
2018.12.13 07:55:01 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.13 07:55:01 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.13 07:55:01 1:     main::CUL_HM_respPendTout           called by fhem.pl (3146)
2018.12.13 07:55:01 1:     main::HandleTimeout                 called by fhem.pl (649)


vielleicht auch noch interessant für euch:

Code Auswählen Erweitern

2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet
2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet


das wird halt vorher gespammt, hatte ich aber schon erwähnt meine ich.

[mgernoth]

Hi,

Uhrzeit ist ne gute Frage. Bei mir läuft FHEM in einem Ubuntu 16.04.2 LTS in einer ESXI VM.

Hmm, VM könnte evtl. ein Problem sein, das ist aber sehr unwahrscheinlich. Manchmal synchronisieren die Hypervisor hart von aussen.

Hier nochmal von heute morgen:

Hoffentlich bevor Du autoReadReg geändert hast?

Code Auswählen Erweitern

2018.12.13 07:55:01 5: HMUARTLGW 4151_PEQ0533636 HMUARTLGW_Write: As1001B00145FF965B124B00050000000000


Ah, Du hast den Vorschlag von noansi umgesetzt
Ist das die einzige HMUARTLGW-Zeile zwischen den Backtraces?

Wenn ja dann ist es eindeutig nicht der Receive-Pfad der da noch dazwischenfunkt.

vielleicht auch noch interessant für euch:

Code Auswählen Erweitern

2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet
2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet


das wird halt vorher gespammt, hatte ich aber schon erwähnt meine ich.

Ja, das ist die Vorstufe des gleichen Problems bis dann irgendwann das Modul aufgibt und die "not initialized" Meldung kommt.

Viele Grüße
  Michael

[gritob]

Hmm, VM könnte evtl. ein Problem sein, das ist aber sehr unwahrscheinlich. Manchmal synchronisieren die Hypervisor hart von aussen.

Die VM Konfiguration habe ich so 100+ Mal laufen wenn ich es abschätzen müsste. Unterschied ist hier jetzt nur, dass es hier sehr viele Wandthermostate gibt. Teilweise habe ich noch größere Systeme am laufen, die jedoch nur aus normalen Thermostaten bestehen und die laufen ohne Fehler. Ich konnte den Fehler jetzt auch nochmal bei einem kleineren System beobachten, da gibt es jedoch auch sehr viele Wandthermostate. Ich vermute wirklich, dass es irgendwie damit zusammenhängen muss. Vielleicht hilft das. Ich teste gerne alles und kann den Fehler denke ich sehr schnell reproduzieren, spätestens dann, wenn ich viele getConfigs mache, kann ich es bestimmt sogar erzwingen. Momentan hab ich so eine Bauernlösung am Laufen, dass mir FHEM in einem cronjob killt, wenn es in den Modus fährt und dann wieder hochfährt. Funktioniert zwar aber kann auch keine Dauerlösung sein 

Ist das die einzige HMUARTLGW-Zeile zwischen den Backtraces?

Leider ja, das was ich gepostet habe steht dann so quasi gefühlt mehrere 100 Male in der Datei. Ist immer ein anderer HMUART.

Hier nochmal nach der autoReadReg Änderung. Hab hier sogar eine Stelle gefunden wo es 2 betrifft:

Code Auswählen Erweitern

2018.12.14 07:35:01 5: HMUARTLGW 4151_PEQ0533636 HMUARTLGW_Write: As1001B00145FF965B124B00050000000000
2018.12.14 07:35:01 1: HMUARTLGW 4151_PEQ0533636: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B00145FF965B124B00050000000000
2018.12.14 07:35:01 1: stacktrace:
2018.12.14 07:35:01 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.14 07:35:01 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.14 07:35:01 1:     main::CUL_HM_respPendTout           called by fhem.pl (3146)
2018.12.14 07:35:01 1:     main::HandleTimeout                 called by fhem.pl (649)
2018.12.14 07:35:01 5: HMUARTLGW 4160_PEQ0533574 HMUARTLGW_Write: As1001B00145FF965C171400050000000000
2018.12.14 07:35:01 1: HMUARTLGW 4160_PEQ0533574: Device not initialized (state: 3, init) but asked to send data. Dropping: As1001B00145FF965C171400050000000000
2018.12.14 07:35:01 1: stacktrace:
2018.12.14 07:35:01 1:     main::HMUARTLGW_Write               called by fhem.pl (1000)
2018.12.14 07:35:01 1:     main::IOWrite                       called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.14 07:35:01 1:     main::CUL_HM_respPendTout           called by fhem.pl (3146)
2018.12.14 07:35:01 1:     main::HandleTimeout                 called by fhem.pl (649)


[noansi]

Hallo Michael,

disconnected in den Logs für HMUARTLGW gibt den Zustand von "cond" wieder, nicht aber den von "state", wie es in CUL_HM_respPendTout Zeile 7131 mit

Code Auswählen Erweitern

    elsif (ReadingsVal($hash->{IODev}->{NAME},"state","") !~ m/^(opened|Initialized)$/){#IO errors
      CUL_HM_eventP($hash,"IOdly");
      CUL_HM_ProcessCmdStack($hash) if($rxt & 0x03);#burst/all
    }

abgefragt wird.

Kann es in dem Zustand bei HMUARTLGW sein, dass "state" auf opened oder Initialized steht, obwohl "cond" disconnected besagt?

Und sollte die Abfrage im CUL_HM code oben nicht eher in

Code Auswählen Erweitern

    elsif (   (defined $hash->{IODev}->{XmitOpen} && $hash->{IODev}->{XmitOpen} < 1)
           || ReadingsVal($hash->{IODev}->{NAME},"state","") !~ m/^(opened|Initialized)$/ ){#IO errors

geändert werden?
Oder noch besser mit Überlastbehandlung.

Gruß, Ansgar.

[noansi]

Hallo Michael, hallo Martin,

der Pfad ab Zeile 7174 wird in den letzten Stacktraces in CUL_HM ausgeführt:

Code Auswählen Erweitern

      else{# normal device resend
        if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
          if ($pHash->{mmcA}){#fillback multi-message command
            unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
            delete $pHash->{mmcA};
            delete $pHash->{mmcS};
           
            my $cmd = shift @{$hash->{cmdStack}};
            $cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
            $pHash->{rspWait}{cmd} = $cmd;
            CUL_HM_responseSetup($hash,$cmd);
          }

          my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
          $pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
        }
        IOWrite($hash, "", $pHash->{rspWait}{cmd});
        CUL_HM_eventP($hash,"SndB")          if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
        CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
        InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
      }


CUL_HM_responseSetup setzt $pHash->{rspWait}{reSent} erneut zurück.
Daher vermute ich mal, es sollte der aktuelle {reSent} Wert in {wuReSent} geschrieben werden.
Also folgender Ergänzungsvorschlag, um ständiges Wiederholen zu unterbinden:

Code Auswählen Erweitern

      else{# normal device resend
        if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
          if ($pHash->{mmcA}){#fillback multi-message command
            unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
            delete $pHash->{mmcA};
            delete $pHash->{mmcS};
           
            my $cmd = shift @{$hash->{cmdStack}};
            $cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
            $pHash->{rspWait}{cmd} = $cmd;
            $pHash->{wuReSent} = $pHash->{rspWait}{reSent};# save 'invalid' count
            CUL_HM_responseSetup($hash,$cmd);
          }

          my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
          $pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
        }
        IOWrite($hash, "", $pHash->{rspWait}{cmd});
        CUL_HM_eventP($hash,"SndB")          if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
        CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
        InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
      }


Zur zur ständigen Wiederholung gehört aber auch, dass die Funkverbindung zum device schlecht sein müsste, oder es die Message nicht beantwortet?
Oder die message gar nicht gesendet wird und deswegen keine Antwort kommt.

Gruß, Ansgar.

[XXL-Wing]

Hallo,

Update von meiner Seite...
Die Logeinträge mit dauerhaften retries sind mit dem neuen ack im Code ausgeblieben, die permanenten disconnects des LAN Configdaapters sind aber geblieben...
Das zweite LAN-GW hat derartige Probleme nicht.
Netzwerkprobleme kann ich ausschließen, der Switch hat nix in den Management logs und auch andere Geräte am selben Switch haben stabile Verbindung...
Firmware Version des LAN-CFG ist    
0.964

LG
Mike

[frank]

dann mach mal ein update auf 0.965.

[gritob]

Hallo Michael, hallo Martin,

der Pfad ab Zeile 7174 wird in den letzten Stacktraces in CUL_HM ausgeführt:

Code Auswählen Erweitern

      else{# normal device resend
        if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
          if ($pHash->{mmcA}){#fillback multi-message command
            unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
            delete $pHash->{mmcA};
            delete $pHash->{mmcS};
           
            my $cmd = shift @{$hash->{cmdStack}};
            $cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
            $pHash->{rspWait}{cmd} = $cmd;
            CUL_HM_responseSetup($hash,$cmd);
          }

          my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
          $pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
        }
        IOWrite($hash, "", $pHash->{rspWait}{cmd});
        CUL_HM_eventP($hash,"SndB")          if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
        CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
        InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
      }


CUL_HM_responseSetup setzt $pHash->{rspWait}{reSent} erneut zurück.
Daher vermute ich mal, es sollte der aktuelle {reSent} Wert in {wuReSent} geschrieben werden.
Also folgender Ergänzungsvorschlag, um ständiges Wiederholen zu unterbinden:

Code Auswählen Erweitern

      else{# normal device resend
        if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
          if ($pHash->{mmcA}){#fillback multi-message command
            unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
            delete $pHash->{mmcA};
            delete $pHash->{mmcS};
           
            my $cmd = shift @{$hash->{cmdStack}};
            $cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
            $pHash->{rspWait}{cmd} = $cmd;
            $pHash->{wuReSent} = $pHash->{rspWait}{reSent};# save 'invalid' count
            CUL_HM_responseSetup($hash,$cmd);
          }

          my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
          $pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
        }
        IOWrite($hash, "", $pHash->{rspWait}{cmd});
        CUL_HM_eventP($hash,"SndB")          if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
        CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
        InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
      }


Zur zur ständigen Wiederholung gehört aber auch, dass die Funkverbindung zum device schlecht sein müsste, oder es die Message nicht beantwortet?
Oder die message gar nicht gesendet wird und deswegen keine Antwort kommt.

Gruß, Ansgar.

vielleicht nochmal zur info. hab mal die zeile gestern hinzugefügt und bis jetzt ist es noch nicht wieder aufgetreten! ich werde weiterhin beobachten und mich melden.

nachtrag 19.12: bis jetzt immer noch nicht aufgetreten. ich gebe jetzt mal etwas last auf das system mit einigen befehlen um zu sehen, wie es sich dann verhält.

[gritob]

Nach 10 Tagen ist es immer noch wieder nicht aufgetreten Anscheinend habt ihr es gelöst für mich!

[noansi]

Hallo gritob,

und was passiert, wenn Du die Zeile nochmal raus nimmst?
Martin wird es wohl nur in die aktuelle Version einbauen, wenn es sich reproduzieren lässt.

Gruß, Ansgar.

[gritob]

Hallo gritob,

und was passiert, wenn Du die Zeile nochmal raus nimmst?
Martin wird es wohl nur in die aktuelle Version einbauen, wenn es sich reproduzieren lässt.

Gruß, Ansgar.

Dann kommt es wieder! Hab den Fehler jetzt auch bei nem anderen System gesehen wo es auch viele Wandthermostate gibt. Hab die Zeile dann 1-2 Mal ein- und auskommentiert. Es verschwindet und kommt dann wieder, je nachdem. Also hier funktioniert es wirklich einwandfrei. Weiss zwar nicht was ihr gemacht habt aber die Änderung aus dem letzten Post reicht aus für die Behebung.

[martinp876]

das mit Ansgars Fix kann ich nicht nachvollziehen.
hier meine Fragen:
- Das problematische Device ist ein EP oder en TC?
- es ist immer das gleiche device?
- msgRepeat ist auf 1 gesetzt - damit wird max ein mal wiederholt (darf werden...)
- wenn der Fehler passiert werden nachrichten kontinuierlich wiederholt - alle 3 sec?

wenn der Fehler auftritt bitte
- verbose dieses Device auf 5 setzen
- beim HMLAN das Attribut logId setzen auf die HMid des problematischen Device.
- ein List des Device wenn der Fehler ansteht.

[noansi]

Hallo Martin,

ein Problemdevice ist ein TC. Das List war hier https://forum.fhem.de/index.php/topic,94035.msg870405.html#msg870405.

Problematische messages sind Burst messages gewesen, wie Michael schon bemerkt hatte, https://forum.fhem.de/index.php/topic,94035.msg871132.html#msg871132.

msgRepeat steht beim dem list auf 1, das hat mich auch gewundert, warum es bei dem mit der einen Zeile als Fix helfen sollte. Aber vielleicht war es ein temporärer Zustand. @gritob:
Daher bitte ein aktuelles "frisches" list.

Mehr Infos müssen die User mit Problemen versuchen zu liefern. Eventuell mal mit verbose 5 ab Systemstart für das HMLAN, damit die Vorgeschichte klarer wird.

Gruß, Ansgar.

[gritob]

das mit Ansgars Fix kann ich nicht nachvollziehen.
hier meine Fragen:
- Das problematische Device ist ein EP oder en TC?
- es ist immer das gleiche device?
- msgRepeat ist auf 1 gesetzt - damit wird max ein mal wiederholt (darf werden...)
- wenn der Fehler passiert werden nachrichten kontinuierlich wiederholt - alle 3 sec?

wenn der Fehler auftritt bitte
- verbose dieses Device auf 5 setzen
- beim HMLAN das Attribut logId setzen auf die HMid des problematischen Device.
- ein List des Device wenn der Fehler ansteht.

Frohes Neues, ich kann es bei Gelegenheit nochmal machen. Gibt da nur 1-2 Probleme.

- Ist ein TC
- es ist nicht immer das gleiche Device, weder das TC noch HMLAN
- msgRepeat ist immer noch auf 1 korrekt
- die Nachrichten werden nach Log viel häufiger wiederholt, geschätzt hunderte Male pro Sekunde und dann ist fhem auch tot.

- da es immer ein anderes Device ist, ist das mit dem verbose 5 schwierig
- ähnliches Problem hier auch, müsste theoretisch jeden HMLAN auf jedes in der Nähe erreichbare Device loggen lassen
- wenn der Fehler ansteht, dann kann ich leider Fhem gar nicht mehr bedienen. Also auch nicht per telnet.

Komm ich denn sonst noch etwas intelligenter an die Infos die für euch wichtig sind?

[martinp876]

Du kannst auch einfach alle loggen lassen. Ich wollte nur die Größe reduzieren. Läuft bei mir aber kontinuierlich problemlos mit.

[mgernoth]

Hallo Martin,

das mit Ansgars Fix kann ich nicht nachvollziehen.

Bei einem Burst-Device kann folgendes passieren:

• CUL_HM_respPendTout inkrementiert $pHash->{rspWait}{reSent} (Zeile 7207)
• CUL_HM_respPendTout ruft CUL_HM_responseSetup auf (Zeile 7245)
• CUL_HM_responseSetup liest die resends nur aus $hash->{helper}{prt}{wuReSent} und wenn das leer ist wird 1 angenommen (Zeile 6830ff)
• CUL_HM_responseSetup ruft CUL_HM_respWaitSu mit diesen "falschen" Wert auf (an mehreren Stellen)
• CUL_HM_respWaitSu überschreibt das reSent im Device-Hash mit dem falschen Wert (Zeile 6811)

Damit gibt es dann ein endloses resend, da reSent nie die 3 erreicht.

Ansgars fix setzt vor dem Aufruf von CUL_HM_responseSetup den Wert von $hash->{helper}{prt}{wuReSent} auf den Wert aus $hash->{rspWait}{reSent} und verhindert so das überschreiben. Evtl. ist der korrekte fix aber, in CUL_HM_responseSetup die Variable $rss nicht nur auf den Wert aus $hash->{helper}{prt}{wuReSent} zu setzen sondern auch in $hash->{rspWait}{reSent} zu schauen.

Viele Grüße
  Michael

[noansi]

Hallo Michael, hallo Martin,

danke für's mitschauen!

Ich hatte mich zum Fix an Zeile 7230 und  7233 orientiert, das schien mir wegen der Nähe verständlicher und beeinflusst nicht die bisherige Funktion von CUL_HM_responseSetup/CUL_HM_respWaitSu, um nicht auf die schnelle den Teufel mit dem Beelzebub auszutreiben.

Auch wenn das Attribut msgRepeat auf 1 gesetzt ist, wird bei Zeile 7195 der Spuck nicht beendet, da erst in der Folge auf 2 erhöht wird, dann aber in CUL_HM_responseSetup/CUL_HM_respWaitSu für ein Burst device wieder zu 1 wird.

$hash->{rspWait}{reSent}

hatte ich als $hash->{helper}{prt}{rspWait}{reSent} verstanden?!

Gruß, Ansgar.

[martinp876]

@Michael,

gute Analyse.
Das Problem ist 2. Ich nutze die Burst settings - aber das reSent wird gelöscht.
Ich rette es nun vorher.
@Ansgar: wuReSent macht auch so etwas - aber da es schon namentlich auch für Wakeup ist sollte man es nicht misbrauchen

comming today - danke euch beiden.