[HM485] keine neuen Homematic devices (autocreate) - Queue Problem

[loetmeister]

Hallo,

ich habe ab und zu ein Problem, dass keine neuen Homematic Wired Geräte angelegt werden. Nach einen FHEM Neustart geht es wieder.
Das Problem hatte ich schon länger, aber mir jetzt erst genauer angeschaut.
Es scheint als sende HM485_LAN nichts mehr (kein "hm485: TX:" im log)

Im Fehlerfall sie es so aus: Es kommt eine announce Nachricht und es wird die 68(h) deviceType Nachricht in die queue eingestellt, aber nicht gesendet.
Nach dem log Eintrag "HM485_QueueStart" geht es nicht weiter.
Neustart des hm485d bringt nichts...

Code Auswählen Erweitern

2020.09.28 18:13:07 5: hm485: HM485_Parse: MsgId: 0
2020.09.28 18:13:07 5: hm485: HM485_Parse: ProcessEvent
2020.09.28 18:13:07 5: hm485: HM485_ProcessEvent: hmwId = 42000077 msgData = 41007101001448425737323936333735
2020.09.28 18:13:07 4: hm485: Device 42000077 not defined yet. We need the type for autocreate
2020.09.28 18:13:07 5: hm485: HM485_QueueCommand68
2020.09.28 18:13:07 5: hm485: HM485_QueueStart: Num: 273

Es ist dabei zu betonen, dass ich im Fehlerfall bereits angelegt Geräte ganz normal über FHEM ansprechen kann. Also Senden und Empfangen geht... bloß für autocreate nicht... 


So sieht es dann nach einem FHEM Neustart aus.
"type" wird abgefragt, dann " serial number", usw.

Code Auswählen Erweitern

2020.09.28 18:30:22 5: hm485: HM485_Parse: MsgId: 0
2020.09.28 18:30:22 5: hm485: HM485_Parse: ProcessEvent
2020.09.28 18:30:22 5: hm485: HM485_ProcessEvent: hmwId = 42000077 msgData = 41007101001448425737323936333735
2020.09.28 18:30:22 4: hm485: Device 42000077 not defined yet. We need the type for autocreate
2020.09.28 18:30:22 5: hm485: HM485_QueueCommand68
2020.09.28 18:30:22 5: hm485: HM485_QueueStart: Num: 0
2020.09.28 18:30:22 5: hm485: HM485_QueueProcessStep: HASH(0x34764b8)
2020.09.28 18:30:22 5: hm485: HM485_LAN_Write TX: 214
2020.09.28 18:30:22 5: hm485: HM485_LAN_SendQueueNextItem: QID: 000001D4
2020.09.28 18:30:22 5: SW: fd0dd653c8420000771a0000000168
2020.09.28 18:30:22 4: hm485: hm485: TX: (214) I[1](0,F,B)(1A) 00000001 -> 42000077 [3] 68(h)
2020.09.28 18:30:22 5: hm485: HM485_QueueSetRequestId start
2020.09.28 18:30:22 5: hm485: HM485_QueueSetRequestId: Id: 214
2020.09.28 18:30:23 5: hm485: HM485_LAN_parseIncommingCommand: MsgId: 214 Cmd: 114
2020.09.28 18:30:23 5: hm485: HM485_LAN_parseIncommingCommand: Response: (214) 7101
2020.09.28 18:30:23 5: hm485: Dispatch: FD05D672387101
2020.09.28 18:30:23 5: hm485: dispatch ▒\005▒r8q\001
2020.09.28 18:30:23 5: hm485: HM485_Parse: MsgId: 214
2020.09.28 18:30:23 5: hm485: HM485_Parse: ProcessResponse
2020.09.28 18:30:23 5: hm485: HM485_ProcessResponse: msgData = 7101
2020.09.28 18:30:23 4: hm485: Device 42000077 not defined yet. We need the serial number for autocreate
2020.09.28 18:30:23 5: hm485: HM485_QueueCommand6E
2020.09.28 18:30:23 5: hm485: HM485_QueueStart: Num: 1
2020.09.28 18:30:23 5: hm485: HM485_QueueStepSuccess called
2020.09.28 18:30:23 5: hm485: HM485_QueueStepSuccess: Entries: 0 Index: 0
2020.09.28 18:30:23 5: hm485: HM485_QueueProcessStep: HASH(0x3477eb0)
2020.09.28 18:30:23 5: hm485: HM485_LAN_parseIncommingCommand: Removing Queue 000001D4
2020.09.28 18:30:23 5: hm485: HM485_LAN_Write TX: 215
...




Gruß,
Thomas

[Thorsten Pferdekaemper]

Hi,

im Prinzip wäre es großartig, wenn das endlich mal jemand wirklich nachvollziehen könnte. Bisher hatte ich den Effekt auch schon sporadisch, aber immer wenn ich dem auf den Grund gehen wollte, ist es nicht mehr passiert.
Vielleicht erst ein bisschen Erklärung dazu: Es gibt im FHEM-Modul ein System von Queues für Sachen, bei denen man ein Kommando nach dem anderen absetzen und auf die Antworten warten muss. Das ist z.B. das Autocreate, weil man da nacheinender bestimmte Attribute vom Gerät abfragt. Außerdem das getConfig, da man da so ziemlich das ganze EEPROM auslesen muss.
Allerdings bezieht sich das "nacheinander" immer auf ein Gerät. D.h. jedes Gerät (oder sogar jeder Vorgang) hat seine eigene Queue. Das bedeutet auch, dass wenn eine Queue abgebrochen wird, weil irgendwo eines der Kommandos fehlschlägt, dann sollte die nächste Queue angefangen werden. (Z.B. wenn FHEM hochfährt wird für jedes Gerät ein getConfig gemacht. Wenn eins davon schiefgeht, dann sollen die anderen trotzdem weiterlaufen.)
Im Prinzip sollte es so sein, dass eine Queue entweder durchläuft oder abbricht (im Zweifelsfall durch einen Timeout). In beiden Fällen wird die Queue weggeworfen und die nächste angefangen (wenn es eine nächste gibt). Irgendwie scheint das aber bei Dir nicht zu funktionieren. Der letzte Eintrag in Deinem Log (das mit dem Fehler) sagt mir, dass es 273 Queues gibt, es scheint aber nichts zu laufen.

Dass in dem Zustand das Senden und Empfangen trotzdem funktioniert ist klar, da normale Kommandos nicht über diese Queues abgewickelt werden. Die gehen einfach so durch. Allerdings habe ich im Coding irgendwo einen Kommentar hinterlassen, dass solche "normalen" Kommandos und die Queues sich gegenseitig stören könnten. Ich weiß allerdings nicht mehr, was ich mir dabei gedacht hatte.

Ich habe mir das Coding jetzt nochmal genauer angeschaut, aber ich weiß nicht, was da schief gehen könnte. Möglicherweise landet doch was in den Queues, was dort nichts zu suchen hat.
Wenn das wieder auftritt, könntest Du dann mal das hier in das Kommandofeld eingeben:

Code Auswählen Erweitern


{ Dumper(\@main::msgQueueList) }

...und mir das Ergebnis hier reinkopieren?

Gruß,
   Thorsten

[loetmeister]

Hallo Thorsten,

EDIT: Danke für die Erklärung. Das Verhalten, das du beschreibst, deckt sich mit meinen Beobachtungen. Kein autocreate und kein getConfig, der Rest ist ok; "normalen" Kommandos und die Queues, erklärt es..

Der Befehl gibt nur $VAR1 = []; aus.

Im log sehe ich aktuell aber

Code Auswählen Erweitern

2020.10.05 13:55:11 5 : hm485: HM485_LAN_parseIncommingCommand: MsgId: 0 Cmd: 101
2020.10.05 13:55:11 4 : hm485: Event:HASH(0x33067b0)
2020.10.05 13:55:11 5 : hm485: Dispatch: FD0F0065FFFFFFFFF8608F3D0A4B05000A
2020.10.05 13:55:11 5 : hm485: dispatch �\017\000e�����`�=\nK\005\000\n
2020.10.05 13:55:11 5 : hm485: HM485_Parse: MsgId: 0
2020.10.05 13:55:11 5 : hm485: HM485_Parse: ProcessEvent
2020.10.05 13:55:11 5 : hm485: HM485_ProcessEvent: hmwId = 608F3D0A msgData = 4B05000A
2020.10.05 13:55:11 4 : hm485: Device 608F3D0A not defined yet. We need the type for autocreate
2020.10.05 13:55:11 5 : hm485: HM485_QueueCommand68
2020.10.05 13:55:11 5 : hm485: HM485_QueueStart: Num: 186
2020.10.05 13:55:16 5 : hm485: HM485_LAN_parseIncommingCommand: MsgId: 0 Cmd: 101
2020.10.05 13:55:16 4 : hm485: Event:HASH(0x331c918)
2020.10.05 13:55:16 5 : hm485: Dispatch: FD0F0065FFFFFFFFFA608F3D0A4B03000A
2020.10.05 13:55:16 5 : hm485: dispatch �\017\000e�����`�=\nK\003\000\n
2020.10.05 13:55:16 5 : hm485: HM485_Parse: MsgId: 0
2020.10.05 13:55:16 5 : hm485: HM485_Parse: ProcessEvent
2020.10.05 13:55:16 5 : hm485: HM485_ProcessEvent: hmwId = 608F3D0A msgData = 4B03000A
2020.10.05 13:55:16 4 : hm485: Device 608F3D0A not defined yet. We need the type for autocreate
2020.10.05 13:55:16 5 : hm485: HM485_QueueCommand68
2020.10.05 13:55:16 5 : hm485: HM485_QueueStart: Num: 187
2020.10.05 13:55:18 5 : hm485: HM485_LAN_parseIncommingCommand: MsgId: 0 Cmd: 101
2020.10.05 13:55:18 4 : hm485: Event:HASH(0x323b598)
2020.10.05 13:55:18 5 : hm485: Dispatch: FD0F0065FFFFFFFFFC608F3D0A4B01000A
2020.10.05 13:55:18 5 : hm485: dispatch �\017\000e�����`�=\nK\001\000\n
2020.10.05 13:55:18 5 : hm485: HM485_Parse: MsgId: 0
2020.10.05 13:55:18 5 : hm485: HM485_Parse: ProcessEvent
2020.10.05 13:55:18 5 : hm485: HM485_ProcessEvent: hmwId = 608F3D0A msgData = 4B01000A
2020.10.05 13:55:18 4 : hm485: Device 608F3D0A not defined yet. We need the type for autocreate
2020.10.05 13:55:18 5 : hm485: HM485_QueueCommand68
2020.10.05 13:55:18 5 : hm485: HM485_QueueStart: Num:188


Gruß,
Thomas

[loetmeister]

Hallo,

Es gibt noch eine zweite Abwandlung... das device wird zwar angelegt, es läuft aber in eine Schleife bei Abfrage des deviceType, Version, etc.
Innerhalb ein paar Minuten wird es 740 mal versucht
root@haus:~# grep ".*2020.10.06.*Initialisierungsfehler.*608F40E7.*" /opt/fhem/log/fhem-2020-10.log | wc -l
740

Das lässt sich durch löschen des Devices stoppen, danach fährt "autocreate" wieder gegen die Wand. Eventuell wird da eine queue referenziert, die durch das Löschen nicht mehr da ist? ... bzw. irgendwie "hängt"?

Hier ein Durchlauf:

Code Auswählen Erweitern

2020.10.06 22:56:15 3: HBW_SD6_Multikey_v1_HBW0000999: Initialisierungsfehler 608F40E7 DeviceKey noch nicht vorhanden
2020.10.06 22:56:15 5: hm485: HM485_GetNewMsgQueue
2020.10.06 22:56:15 3: hm485: Initialisierung von Modul 608F40E7
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: Removing Queue 00000970
2020.10.06 22:56:15 5: hm485: HM485_LAN_Write TX: 167
2020.10.06 22:56:15 5: hm485: HM485_LAN_SendQueueNextItem: QID: 00000971
2020.10.06 22:56:15 5: SW: fd0da753c8608f40e71c0000000168
2020.10.06 22:56:15 4: hm485: hm485: TX: (167) I[2](0,F,B)(1C) 00000001 -> 608F40E7 [3] 68(h)
2020.10.06 22:56:15 5: hm485: HM485_QueueSetRequestId start
2020.10.06 22:56:15 5: hm485: HM485_QueueSetRequestId: Id: 167
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: MsgId: 167 Cmd: 114
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: Response: (167) B101
2020.10.06 22:56:15 5: hm485: Dispatch: FD05A772DCB101
2020.10.06 22:56:15 5: hm485: dispatch ▒\005▒rܱ\001
2020.10.06 22:56:15 5: hm485: HM485_Parse: MsgId: 167
2020.10.06 22:56:15 5: hm485: HM485_Parse: ProcessResponse
2020.10.06 22:56:15 5: hm485: HM485_ProcessResponse: msgData = B101
2020.10.06 22:56:15 5: hm485: HM485_ProcessResponse: device = 608F40E7 requestType = 68 requestData =  msgData = B101
2020.10.06 22:56:15 5: hm485: HM485_QueueStepSuccess called
2020.10.06 22:56:15 5: hm485: HM485_QueueStepSuccess: Entries: 2 Index: 0
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: Removing Queue 00000971
2020.10.06 22:56:15 5: hm485: HM485_LAN_Write TX: 168
2020.10.06 22:56:15 5: hm485: HM485_LAN_SendQueueNextItem: QID: 00000972
2020.10.06 22:56:15 5: SW: fd0da853c8608f40e71e000000016e
2020.10.06 22:56:15 4: hm485: hm485: TX: (168) I[3](0,F,B)(1E) 00000001 -> 608F40E7 [3] 6E(n)
2020.10.06 22:56:15 5: hm485: HM485_QueueSetRequestId start
2020.10.06 22:56:15 5: hm485: HM485_QueueSetRequestId: Id: 168
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: MsgId: 168 Cmd: 114
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: Response: (168) 48425730303030393939
2020.10.06 22:56:15 5: hm485: Dispatch: FD0DA872FE48425730303030393939
2020.10.06 22:56:15 5: hm485: dispatch ▒\r▒r▒HBW0000999
2020.10.06 22:56:15 5: hm485: HM485_Parse: MsgId: 168
2020.10.06 22:56:15 5: hm485: HM485_Parse: ProcessResponse
2020.10.06 22:56:15 5: hm485: HM485_ProcessResponse: msgData = 48425730303030393939
2020.10.06 22:56:15 5: hm485: HM485_ProcessResponse: device = 608F40E7 requestType = 6E requestData =  msgData = 48425730303030393939
2020.10.06 22:56:15 5: hm485: HM485_QueueStepSuccess called
2020.10.06 22:56:15 5: hm485: HM485_QueueStepSuccess: Entries: 2 Index: 1
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: Removing Queue 00000972
2020.10.06 22:56:15 5: hm485: HM485_LAN_Write TX: 169
2020.10.06 22:56:15 5: hm485: HM485_LAN_SendQueueNextItem: QID: 00000973
2020.10.06 22:56:15 5: SW: fd0da953c8608f40e7180000000176
2020.10.06 22:56:15 4: hm485: hm485: TX: (169) I[0](0,F,B)(18) 00000001 -> 608F40E7 [3] 76(v)
2020.10.06 22:56:15 5: hm485: HM485_QueueSetRequestId start
2020.10.06 22:56:15 5: hm485: HM485_QueueSetRequestId: Id: 169
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: MsgId: 169 Cmd: 114
2020.10.06 22:56:15 5: hm485: HM485_LAN_parseIncommingCommand: Response: (169) 0247
2020.10.06 22:56:15 5: hm485: Dispatch: FD05A972980247
2020.10.06 22:56:15 5: hm485: dispatch ▒\005▒r▒\002G
2020.10.06 22:56:15 5: hm485: HM485_Parse: MsgId: 169
2020.10.06 22:56:15 5: hm485: HM485_Parse: ProcessResponse
2020.10.06 22:56:15 5: hm485: HM485_ProcessResponse: msgData = 0247
2020.10.06 22:56:15 5: hm485: HM485_ProcessResponse: device = 608F40E7 requestType = 76 requestData =  msgData = 0247
2020.10.06 22:56:15 5: hm485: HM485_QueueStepSuccess called
2020.10.06 22:56:15 5: hm485: HM485_QueueStepSuccess: Entries: 2 Index: 2
2020.10.06 22:56:15 3: HBW_SD6_Multikey_v1_HBW0000999: Initialisierungsfehler 608F40E7 DeviceKey noch nicht vorhanden
2020.10.06 22:56:15 5: hm485: HM485_GetNewMsgQueue
2020.10.06 22:56:15 3: hm485: Initialisierung von Modul 608F40E7

...
> HM485_Parse: MsgId: Zählt mehrfach bis 255
> Nach löschen des Device kommt:

2020.10.06 23:00:18 5: hm485: HM485_LAN_parseIncommingCommand: MsgId: 0 Cmd: 101
2020.10.06 23:00:18 4: hm485: Event:HASH(0x2487408)
2020.10.06 23:00:18 5: hm485: Dispatch: FD0F0065FFFFFFFFFC608F40E74B010006
2020.10.06 23:00:18 5: hm485: dispatch ▒\017\000e▒▒▒▒▒`▒@▒K\001\000\006
2020.10.06 23:00:18 5: hm485: HM485_Parse: MsgId: 0
2020.10.06 23:00:18 5: hm485: HM485_Parse: ProcessEvent
2020.10.06 23:00:18 5: hm485: HM485_ProcessEvent: hmwId = 608F40E7 msgData = 4B010006
2020.10.06 23:00:18 4: hm485: Device 608F40E7 not defined yet. We need the serial number for autocreate
2020.10.06 23:00:18 5: hm485: HM485_QueueCommand6E
2020.10.06 23:00:18 5: hm485: HM485_QueueStart: Num: 15
2020.10.06 23:00:18 5: hm485: HM485_LAN_parseIncommingCommand: MsgId: 0 Cmd: 101
2020.10.06 23:00:18 4: hm485: Event:HASH(0x243cda0)
2020.10.06 23:00:18 5: hm485: Dispatch: FD1B0065FFFFFFFFFE608F40E74100B101024748425730303030393939
2020.10.06 23:00:18 5: hm485: dispatch ▒\e\000e▒▒▒▒▒`▒@▒A\000▒\001\002GHBW0000999
2020.10.06 23:00:18 5: hm485: HM485_Parse: MsgId: 0
2020.10.06 23:00:18 5: hm485: HM485_Parse: ProcessEvent
2020.10.06 23:00:18 5: hm485: HM485_ProcessEvent: hmwId = 608F40E7 msgData = 4100B101024748425730303030393939
2020.10.06 23:00:18 4: hm485: Device 608F40E7 not defined yet. We need the serial number for autocreate
2020.10.06 23:00:18 5: hm485: HM485_QueueCommand6E
2020.10.06 23:00:18 5: hm485: HM485_QueueStart: Num: 16

Gruß,
Thomas

[Thorsten Pferdekaemper]

Hi,
sorry, dass ich immer so lange brauche, aber ich habe momentan auch kein Testsystem am Laufen. Da dauert es immer eine Weile, bis ich eine Idee habe.
Ich würde wirklich gerne mal sehen, was in den Queues steht. Natürlich war das vorher Quatsch, da die Queue mit "my" angelegt wird. Da kommt man nicht ganz so leicht dran.
Könntest Du mal in der Datei 10_HM485.pm das folgende Coding reinbasteln:

Code Auswählen Erweitern


sub HM485_DumpQueues() {
return Dumper(\@msgQueueList);
};

...am besten irgendwo ans Ende des Codings, also so ungefähr Zeile 2670 kurz vor der Zeile "1;".

Dann FHEM am Besten mal neu starten. Wenn die Probleme auftreten, dann sollte jetzt das hier in der Kommandozeile einiges an Output bringen:

Code Auswählen Erweitern


{ HM485_DumpQueues( ) }


Vielleicht wäre auch mal interessant, das einzugeben wenn es (noch) keine Probleme gibt.

Gruß,
   Thorsten

[loetmeister]

Hi Thorsten,

danke. Mit der zusätzlichen Funktion geht es... habe mal zwei Ausgaben eingefügt bei denen es ok ist, und eine für den Fehlerfall. Für letzteres wird die Queue mit der Zeit immer länger und 'msgCounter' Zählt weiter hoch. (anscheinend je mehr announce Nachrichten kommen, bzw. sich anstauen)

EDIT: Zu viel Text... daher als Anhang.

Hoffe das Hilft weiter... 

Gruß,
Thomas

[Thorsten Pferdekaemper]

Hi,
also eigentlich müsste der erste Eintrag irgendwann ein NACK bekommen (also ein Timeout vom Device) und dann den Queue-Eintrag wegwerfen. Danach müsste es mit dem nächsten weitergehen. Das scheint irgendwie nicht zu klappen.
...ich muss mir das nochmal etwas genauer ansehen.
Gruß,
   Thorsten

[jove01]

Hallo

Ein HM-LC-BL1PBU-FM hat bei mir seinen Dienst versagt, daher habe ein neues Device angeschlossen.

Doch weder über Anlerntaste oder über SerialNr wird das Device in Fhem angelegt! Beim Pairen über SerialNr geht das Gerät in den Pair_Modus und blinkt.

In Global und im Autocreate ist autosave auf 1. Autosave selber ist aktiv. (Normalerweise inaktiv)

Es passiert auch nichts nach einem Restart von Fhem.

Ich hoffe, Ihr könnt helfen, bedenkt aber bitte, dass ich technisch bezüglich Perl und Raspi wenig Ahnung habe.

Danke
Jürgen

[loetmeister]

Hallo Jürgen,

dein Problem passt hier leider gar nicht rein... hier geht es um Homematic Wired... bzw. dem entsprechenden FHEM Modul.
Ab besten erstellt du einen neuen Thread, oder schaust was es zum Thema "Pairing Probleme bei Homematic Funk" so gibt...

Gruß,
Thomas