HMUARTLGW HMUART_xxx: Device not initialized (state: 99, ok) but asked ...

[marvin78]

Code Auswählen Erweitern

HMUARTLGW HMUART_Keller: Device not initialized (state: 99, ok) but asked to send data. Dropping: As101CA011F14C231E3F630201C80000E101
HMUARTLGW HMUART_Grill unexpected info about Co_CPU_BL received (module crashed?), reopening

Geräte werden nicht geschaltet.

Diese Meldungen melden alle per WLAN eingebundenen 00_HMUARTLGW seit einem Update und Neustart heute morgen (kein Update der HM-Module). Alle sind Teil einer VCCU. Ich habe seit Ewigkeiten keine Änderungen am HM-System vorgenommen und kann mir nicht erklären, wo das herkommt.

Ein Beispiellist eines HMUART (disconnected, weil ich sie geschlossen habe, damit das Gesamtsystem nicht gestört wird-eigentlich zeigen sie Ok an, wenn sie offen sind):

Code Auswählen Erweitern

Internals:
   AssignedPeerCnt 6
   CNT        49
   Clients    :CUL_HM:
   DEF        uart://10.x.x.161:23
   DEVCNT     34
   DevState   0
   DevType    UART
   DeviceName 10.x.x.161:23
   FUUID      5e7a08e8-f33f-be23-8eb8-173850010ed3fce4
   FVERSION   00_HMUARTLGW.pm:0.252030/2021-11-08
   LastOpen   1749823820.75863
   NAME       HMUART_Grill
   NOTIFYDEV  global
   NR         1241
   NTFY_ORDER 47-HMUART_Grill
   RAWMSG     040200
   RSSI       -73
   STATE      closed
   TYPE       HMUARTLGW
   XmitOpen   0
   eventCount 6
   model      HM-MOD-UART
   msgLoadCurrent 0
   msgLoadHistory -/-/-/-/-/-/-/-/-/-/-/-
   msgLoadHistoryAbs 0/-/-/-/-/-/-/-/-/-/-/-/-
   owner_CCU  CCU
   Helper:
     CreditTimer 8
     Initialized 1
     AckPending:
       49:
         cmd        03
         dst        0
         frame      FD00030031033E09
         time       1749823948.19413
     LastSendLen:
       3
       3
     Log:
       IDs:
     RoundTrip:
       Delay      0.0834970474243164
     loadLvl:
       lastHistory 1749823833.07882
   MatchList:
     1:CUL_HM   ^A......................
   PeerQueue:
     HASH(0x564353a523d8)
     HASH(0x5643526372a0)
   Peers:
     20A659     
     241FA4     
     3268BE     
     3E6F7E     +3E6F7E,00,01,00
     5E13AB     
     62D6A1     
     665C6D     
     6A4A45     
     6A4B59     
     6D3091     +6D3091,00,01,00
     6D3204     +6D3204,00,01,00
   READINGS:
     2025-06-13 15:30:09   D-HMIdAssigned  XXXXXX
     2025-06-13 15:30:09   D-HMIdOriginal  488B3F
     2025-06-13 15:30:09   D-firmware      1.4.1
     2025-06-13 16:10:27   D-serialNr     
     2025-06-13 16:09:42   D-type          HM-MOD-UART
     2025-06-13 16:12:28   cond            disconnected
     2025-06-13 16:12:28   load            0
     2025-06-13 16:12:28   loadLvl         suspended
     2025-06-13 16:12:28   state           closed
   helper:
Attributes:
   DbLogExclude .*
   alias      HMUART Grill
   appOptions { "template": "hmlan", "system": "true", "connected": { "watcher": "ActionDetector" } }
   event-on-change-reading state,loadLvl,cond
   group      IODevices
   hmId       XXXXXXX
   icon       hm_usb
   room       Verwaltung->Server
der open Zustand ist so:

Code Auswählen Erweitern

2025-06-13 17:11:42   cond            ok
     2025-06-13 17:11:42   load            0
     2025-06-13 17:11:42   loadLvl         low
     2025-06-13 17:11:38   state           opened
Hat jemand eine Idee dazu?

Edit: mehrere Neustarts, reopen, close, open etc. haben natürlich nicht geholfen.

[marvin78]

Es kommen außerdem mittlerweile noch folgende Meldung:

Code Auswählen Erweitern

HMUARTLGW HMUART_Flur Adding peer 5E1752 failed! You have probably forced an unknown aesKey for this device.
HMUARTLGW HMUART_Flur invalid checksum received, dropping frame (FD0004010E0401B54C)!

Nun ist es aber so, dass der aesKey in der VCCU steht und dort vermutlich schon seit weit über 10 Jahren. Daran hat sich nichts geändert UND die 3 HLMANS können damit auch jedes Gerät weiterhin schalten. Tatsächlich bin ich aktuell ratlos.

[frank]

hm...
spärliche Infos, ohne Kontext, zudem verfremdet.

"checksum" riecht nach schlechtem/gestörtem funk.

"crashed" kenne ich im zusammenhang mit virtuellen devices.

vielleicht mal "roundtrip delay" beobachten?
https://forum.fhem.de/index.php?msg=852060

[marvin78]

Danke aber "verfremdet" habe ich nur Daten, die ohnehin nicht relevant sein können (IP Adresse und HMID und ja, die sind alle korrekt). Welche Daten kann ich noch liefern?

Kontext.Eigentlich ist alles da.

Sehr alte HM Installation mit VCCU, 3 HM-LANS und 3 HMUART per Wifi. Alles tadellos bis zum genannten Neustart. Wir können da gerne ins Detail gehen. Erstmal wollte ich auf Leute hinaus, die schon ähnliche Probleme hatten und die Fehler kennen. Das scheint aber nicht der Fall zu sein. Im Forum gibt es genau einen Beitrag zum "Dropping" Fehler. Da lag es an einer falschen HMID als Attribut im UART. Das kann ich hier ausschließen. Zumal wirklich seit Jahren nichts am HM-Teil der Installation geändert wurde.

Das Wifi ist völlig in Ordnung. Keine Probleme. BidCos-Funk über die 3 etwas anders verteilten HMLANs funktioniert im gesamten Haus und im Garten so gut, dass ich aktuell sogar auf die 3 HMUART verzichten kann. Störungen schließe ich weitgehend aus. Alle 3 HMUART sind gut verteilt im Haus. Dass alle gleichzeitig gleich gestört sind, ist unwahrscheinlich. Virtuelle Devices nutze ich in HM nicht.


Ein Restore hat im Übrigen keine Besserung gebracht. Es liegt also nicht am Update. Die fhem.pl war aktualisiert, aber auch auf dem alten Stand gibt es keinen Unterschied.

Danke für den Tipp mit roundtrip delay. Werde ich mir ansehen. Als erstes baue ich einen neuen HMUART auf und teste den.

[marvin78]

Ergänzung. Das aktivieren von logIDs sys in einem der UART füllt mein Log hiermit:

Code Auswählen Erweitern

2025.06.16 15:11:23.066 0: HMUARTLGW HMUART_Keller roundtrip delay: 0.0054
2025.06.16 15:11:23.066 0: HMUARTLGW HMUART_Keller GetSet Ack: 02, state 98
2025.06.16 15:11:23.065 0: HMUARTLGW HMUART_Keller recv: 00 040200, state 98
2025.06.16 15:11:23.059 0: HMUARTLGW HMUART_Keller send: 00 08
2025.06.16 15:11:22.635 0: HMUARTLGW HMUART_Keller Ack with invalid/old counter received, dropping. We: 31, device: 38, state: 99, msg: 0 040200
2025.06.16 15:11:22.634 0: HMUARTLGW HMUART_Keller recv: 00 040200, state 99
2025.06.16 15:11:08.102 0: HMUARTLGW HMUART_Keller roundtrip delay: 0.0461
2025.06.16 15:11:08.102 0: HMUARTLGW HMUART_Keller GetSet Ack: 02, state 98
2025.06.16 15:11:08.102 0: HMUARTLGW HMUART_Keller recv: 00 040200, state 98
2025.06.16 15:11:08.055 0: HMUARTLGW HMUART_Keller send: 00 08
2025.06.16 15:11:07.613 0: HMUARTLGW HMUART_Keller Ack with invalid/old counter received, dropping. We: 30, device: 37, state: 99, msg: 0 040200
2025.06.16 15:11:07.613 0: HMUARTLGW HMUART_Keller recv: 00 040200, state 99
2025.06.16 15:11:06.529 0: HMUARTLGW HMUART_Keller GetSet Ack: 07, state 90
2025.06.16 15:11:06.528 0: HMUARTLGW HMUART_Keller recv: 01 040701010008, state 90
2025.06.16 15:11:06.483 0: HMUARTLGW HMUART_Keller GetSet Ack: 07, state 93
2025.06.16 15:11:06.483 0: HMUARTLGW HMUART_Keller recv: 01 040701010009FFFFFFFFFFFFFFFF, state 93
2025.06.16 15:11:06.424 0: HMUARTLGW HMUART_Keller GetSet Ack: 07, state 90
2025.06.16 15:11:06.423 0: HMUARTLGW HMUART_Keller recv: 01 040701010009FFFFFFFFFFFFFFFF, state 90
2025.06.16 15:11:06.210 1: HMUARTLGW HMUART_Keller: Device not initialized (state: 90, ok) but asked to send data. Dropping: As0DEA8002F14C233618B701017800
2025.06.16 15:11:06.180 1: HMUARTLGW HMUART_Keller: Device not initialized (state: 90, ok) but asked to send data. Dropping: As0DEB8002F14C233618B701017800
2025.06.16 15:10:52.822 0: HMUARTLGW HMUART_Keller roundtrip delay: 0.0254
2025.06.16 15:10:52.822 0: HMUARTLGW HMUART_Keller GetSet Ack: 02, state 98
2025.06.16 15:10:52.822 0: HMUARTLGW HMUART_Keller recv: 00 040200, state 98
2025.06.16 15:10:52.796 0: HMUARTLGW HMUART_Keller send: 00 08
2025.06.16 15:10:52.778 0: HMUARTLGW HMUART_Keller Ack with invalid/old counter received, dropping. We: 26, device: 36, state: 99, msg: 0 040200
2025.06.16 15:10:52.778 0: HMUARTLGW HMUART_Keller recv: 00 040200, state 99

[frank]

moin marvin,

das log zeigt 3 saubere roundtrip messungen (5.4ms - 46.1ms), ohne probleme.
im vergleich mit den aussagen im verlinkten thread sind das für wlan sensationelle werte. allerdings nur eine momentaufnahme. die streuung über den tag wird sicher noch grösser sein. dein grill-uart zeigt im list zb 83.5ms.

die kommunikation bis zum hmuart scheint also ok zu sein.
die fehlermeldungen sind von anderen aktionen.

Code Auswählen Erweitern

2025.06.16 15:11:23.066 0: HMUARTLGW HMUART_Keller roundtrip delay: 0.0054
2025.06.16 15:11:23.066 0: HMUARTLGW HMUART_Keller GetSet Ack: 02, state 98
2025.06.16 15:11:23.065 0: HMUARTLGW HMUART_Keller recv: 00 040200, state 98
2025.06.16 15:11:23.059 0: HMUARTLGW HMUART_Keller send: 00 08
anbei zum vergleich mal ein plot von meinem hmuart, der direkt am gpio auf einem pi3 sitzt.


############

ich habe den verdacht, dass die hmuarts eventuell ein problem mit ihrem eeprom haben. denn im list beim grill-uart, falls das list an der stelle original ist, sieht der "Peers:" abschnitt seltsam unvollständig aus.
das habe ich so noch nie gesehen.

Code Auswählen Erweitern

   Peers:
     20A659    
     241FA4    
     3268BE    
     3E6F7E     +3E6F7E,00,01,00
     5E13AB    
     62D6A1    
     665C6D    
     6A4A45    
     6A4B59    
     6D3091     +6D3091,00,01,00
     6D3204     +6D3204,00,01,00
was da genau passiert, würde ein log mit logIDs=sys,all plus verbose=5 zeigen, wenn man zb "set restart/reopen" macht. anschliessend jeweils mit einem list des hmuart vergleichen.


############

schon seltsam, dass scheinbar alle 3 hmuarts, das selbe problem haben sollen.
gab es eventuell gewitter, stromausfall oder ähnliches?
oder gab es einen korrupten hmip funkbefehl?
sind alle 3 identisch aufgebaut?

vielleicht mal 10 min stromlos machen und rebooten.
netzteil checken und/oder fw neu aufspielen?
elkos, falls vorhanden, tauschen?

[marvin78]

schon seltsam, dass scheinbar alle 3 hmuarts, das selbe problem haben sollen

Genau das macht mich wahnsinnig. Es gab keinen Anlass und alle 3 haben bis zu dem besagten Neustart von FHEM einwandfrei funktioniert. Nun haben alle 3 das gleiche Problem. Und das schließt ja eigentlich viele der gängigen Lösungen aus. Wenn es einer wäre, wäre er vermutlich einfach raus geflogen und ich hätte nie wieder daran gedacht.

Ich wollte eigentlich testweise einen neuen aufbauen, bin aber nicht dazu gekommen und mir fehlt noch Hardware. Deinen Hinweis mit dem korrupten IP Befehl klingt interessant. Es passt zwar zeitlich nicht 100 Prozent zusammen aber ich habe neulich Geräte an die Raspberrymatic angelernt. Vermutlich teste ich nun ein neu aufspielen der FW als erstes. 

Danke.