Nachrichten bleiben in CUL_MAX SendQueue hängen

cbl · 27 Oktober 2020, 18:59:27

Hallo,

seit ein paar Tagen bleiben die Nachrichten zu zwei Heizkörperthermostaten in der SendQueue des CUL_MAX hängen und blockieren Nachrichten an andere HT. ~~Leere ich die Queue, wird normal mit den anderen HT kommuniziert, bis wieder eine Nachricht an diese beiden problematischen HT rausgeht und in der Queue oben landet.~~ Die Kommunikation ist inzwischen mit allen HT eingestellt. Mein Eindruck vorhin und gestern täuschte. Ich kann mit FHEM mit dem CUL kommunizieren und mir mit den GET-Befehlen des CUL-Devices die Readings aktualisieren lassen (uptime, ...).

Die problematischen HT haben Batterien, die ich erst im Sommer ausgetauscht hat und funktionieren manuell bei Tastenbedienung auch normal. Sie kommunizieren lediglich nicht mehr mit dem CUL. Auch ein neues Pairing gerade hat nichts geändert.
FHEM neugestartet habe ich auch seit Freitag einige Male. Die initial leere Queue füllt sich in Abhängigkeit meiner Heizkörpersteuerung mit neuen Befehlen, die nicht abgearbeitet werden.
Die letzten Readingupdates gab es z.B. für batteryState und desiredTemperature am Freitag um 23:39 Uhr. Da habe ich schon längst geschlafen und war (im Urlaub) auch die Stunden davor nicht auf dem System irgendwie aktiv.

Im EventLog sehe ich mit Verbose=5 "CUL cul UNKNOWNCODE Z0F00046015A6AC0000000019182400D0". Wer sendet den und weshalb ist der unbekannt?

10mCredits sollte es genug geben, da ich keine zusätzlichen Geräte in Betrieb genommen habe und auch an der Kommunikation (Max Scanner, ...) nichts verändert habe. Ich sehe aber gerade bei längerer Betrachtung des Eventlog, dass es wohl doch fehlende 10mCredits sind. Direkt nach dem Leeren der Queue (bzw. Neustart) landet ein Befehl von mir in der Queue und wartet auf Abarbeitung, weil nicht genug Credits vorhanden sind. Wie bekomme ich raus, wer die aufbraucht? Über diesen CUL laufen die Heizkörperthermostate und einige Fensterkontakte (wobei alle Fenster seit Stunden geschlossen sind).

Wo könnte noch eine Fehlerquelle sein, die ich gerade übersehe?

Gruß
Christian

Wzut · 27 Oktober 2020, 20:10:25

wie immer :
1. list vom CUL und cm Device
2. verbose 5 am cm Device und Log posten

cbl · 28 Oktober 2020, 07:07:25

Code Auswählen

Internals:
   CMDS       BbCFiAZNkGMKUYRTVWXefmLltux
   Clients    :FS20:FHT.*:KS300:USF1000:BS:HMS:FS20V: :CUL_EM:CUL_WS:CUL_FHTTK:CUL_HOERMANN: :ESA2000:CUL_IR:CUL_TX:Revolt:IT:UNIRoll:SOMFY: :STACKABLE_CC:TSSTACKED:STACKABLE:CUL_RFR::CUL_TCM97001:CUL_REDIRECT:
   DEF        cul.fritz.box:2000 1234
   DeviceName cul.fritz.box:2000
   FD         22
   FHTID      1234
   FUUID      5c446f66-f33f-ae1f-dc37-f7c68ebc74768fde
   NAME       cul.maxcul
   NR         69
   NR_CMD_LAST_H 33
   PARTIAL    
   RAWMSG     Z0EAE020215A549123456000119001E04
   RSSI       -72
   STATE      Initialized
   TYPE       CUL
   VERSION    V 1.66 CUL868
   cul.maxcul_MSGCNT 1444
   cul.maxcul_TIME 2020-10-28 06:51:13
   initString X21
   Helper:
     DBLOG:
       credit10ms:
         DbLog:
           TIME       1603862518.16814
           VALUE      114
       state:
         DbLog:
           TIME       1603864273.43187
           VALUE      UNKNOWNCODE Z0EAE020215A549123456000119001E
   MatchList:
     0:FS20V    ^81..(04|0c)..0101a001......00[89a-f]...
     1:USF1000  ^81..(04|0c)..0101a001a5ceaa00....
     2:BS       ^81..(04|0c)..0101a001a5cf
     3:FS20     ^81..(04|0c)..0101a001
     4:FHT      ^81..(04|09|0d)..(0909a001|83098301|c409c401)..
     5:KS300    ^810d04..4027a001
     6:CUL_WS   ^K.....
     7:CUL_EM   ^E0.................$
     8:HMS      ^810e04......a001
     9:CUL_FHTTK ^T[A-F0-9]{8}
     A:CUL_RFR  ^[0-9A-F]{4}U.
     B:CUL_HOERMANN ^R..........
     C:ESA2000  ^S................................$
     D:CUL_IR   ^I............
     E:CUL_TX   ^TX[A-F0-9]{10}
     F:Revolt   ^r......................$
     G:IT       ^i......
     H:STACKABLE_CC ^\*
     I:UNIRoll  ^[0-9A-F]{5}(B|D|E)
     J:SOMFY    ^Y[r|t|s]:?[A-F0-9]+
     K:CUL_TCM97001 ^s[A-F0-9]+
     L:CUL_REDIRECT ^o+
     M:TSSTACKED ^\*
     N:STACKABLE ^\*
   OLDREADINGS:
   READINGS:
     2020-10-27 19:27:07   ccconf          freq:868.300MHz bWidth:101KHz rAmpl:33dB sens:8dB
     2020-10-27 19:27:30   cmds             B b C F i A Z N k G M K U Y R T V W X e f m L l t u x
     2020-10-28 06:51:18   credit10ms      8
     2020-10-28 06:51:13   state           Initialized
     2020-10-27 19:10:41   uptime          72 06:54:08
     2020-10-27 19:10:49   version         V 1.66 CUL868
   XMIT_TIME:
     1603860759.23991
     1603860868.27702
     1603860977.79729
     1603861087.31308
     1603861196.87762
     1603861306.14936
     1603861415.66329
     1603861525.17842
     1603861634.69297
     1603861743.78724
     1603861853.30723
     1603861962.82279
     1603862072.33832
     1603862181.85614
     1603862294.87006
     1603862406.13118
     1603862518.30351
     1603862630.7677
     1603862962.96783
     1603862968.98111
     1603862975.49725
     1603863069.01098
     1603863322.07343
     1603863328.58574
     1603863397.10092
     1603863506.6358
     1603863862.26063
     1603863868.7727
     1603863875.28658
     1603863945.30186
     1603864054.31739
     1603864162.83513
     1603864272.35204
   powerMap:
   readingsDesc:
     pM_consumption:
       rtype      w
     pM_energy:
       rtype      whr
Attributes:
   DbLogExclude .*
   DbLogInclude credit10ms,state
   event-min-interval credit10ms:1800
   icon       cul_max
   model      CUL
   rfmode     MAX
   room       CUL

Die SendQueue war um 06:55:00 Uhr leer.

Code Auswählen

2020.10.28 06:55:25 4 : cul.max, send -> cmd:SetTemperature, msgcnt:f1, flags:00, Cmd2id:40, src:MAX_123456 , dst:og.arbeitszimmer.heizung , gid:00 , payload:66 , cul:none
2020.10.28 06:55:25 5 : cul.max, send packet: 0bf100401234561507380066
2020.10.28 06:55:25 5 : cul.max, Send Queue 1 packet in queue
2020.10.28 06:55:25 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 145, cul.maxcul CMD_LAST_H: 33
2020.10.28 06:55:25 4 : cul.max, Send Queue packet send : Zs0bf100401234561507380066 to og.arbeitszimmer.heizung with cul.maxcul
2020.10.28 06:55:26 5 : cul.max, Send Queue 1 packet in queue
2020.10.28 06:55:26 5 : cul.max, Send Queue 1 packet in queue
2020.10.28 06:55:27 5 : cul.max, Send Queue 1 packet in queue
2020.10.28 06:55:27 5 : cul.max, Send Queue 1 packet in queue
2020.10.28 06:55:28 5 : cul.max, Send Queue 1 packet in queue
2020.10.28 06:55:28 4 : cul.max, Send Queue retry og.arbeitszimmer.heizung for SetTemperature count: 3
2020.10.28 06:55:31 5 : cul.max, Send Queue 1 packet in queue
2020.10.28 06:55:31 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 42, cul.maxcul CMD_LAST_H: 33
2020.10.28 06:55:31 2 : cul.max, cul.maxcul not enough credit! credit10ms is 42, but we need 110. Waiting 68 seconds. Currently 1 messages are waiting to be sent
2020.10.28 06:55:33 4 : cul.max, send -> cmd:SetTemperature, msgcnt:81, flags:00, Cmd2id:40, src:MAX_123456 , dst:eg.wohnzimmer.heizung.esszimmerfenster , gid:00 , payload:65 , cul:none
2020.10.28 06:55:33 5 : cul.max, send packet: 0b81004012345614100d0065
2020.10.28 06:55:42 4 : cul.max, send -> cmd:SetTemperature, msgcnt:b5, flags:00, Cmd2id:40, src:MAX_123456 , dst:og.kinderschlafzimmer.heizung , gid:00 , payload:64 , cul:none
2020.10.28 06:55:42 5 : cul.max, send packet: 0bb5004012345615a5f70064
2020.10.28 06:56:40 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:56:40 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 111, cul.maxcul CMD_LAST_H: 33
2020.10.28 06:56:40 4 : cul.max, Send Queue packet send : Zs0bf100401234561507380066 to og.arbeitszimmer.heizung with cul.maxcul
2020.10.28 06:56:41 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:56:42 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:56:42 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:56:43 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:56:43 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:56:43 4 : cul.max, Send Queue retry og.arbeitszimmer.heizung for SetTemperature count: 2
2020.10.28 06:56:46 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:56:46 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 7, cul.maxcul CMD_LAST_H: 33
2020.10.28 06:56:46 2 : cul.max, cul.maxcul not enough credit! credit10ms is 7, but we need 110. Waiting 103 seconds. Currently 3 messages are waiting to be sent
2020.10.28 06:58:30 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:58:30 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 111, cul.maxcul CMD_LAST_H: 33
2020.10.28 06:58:30 4 : cul.max, Send Queue packet send : Zs0bf100401234561507380066 to og.arbeitszimmer.heizung with cul.maxcul
2020.10.28 06:58:31 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:58:32 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:58:32 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:58:33 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:58:33 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:58:33 4 : cul.max, Send Queue retry og.arbeitszimmer.heizung for SetTemperature count: 1
2020.10.28 06:58:36 5 : cul.max, Send Queue 3 packets in queue
2020.10.28 06:58:36 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 8, cul.maxcul CMD_LAST_H: 33
2020.10.28 06:58:36 2 : cul.max, cul.maxcul not enough credit! credit10ms is 8, but we need 110. Waiting 102 seconds. Currently 3 messages are waiting to be sent
2020.10.28 07:00:00 4 : cul.max, send -> cmd:SetTemperature, msgcnt:b6, flags:00, Cmd2id:40, src:MAX_123456 , dst:og.kinderschlafzimmer.heizung , gid:00 , payload:67 , cul:none
2020.10.28 07:00:00 5 : cul.max, send packet: 0bb6004012345615a5f70067
2020.10.28 07:00:00 4 : cul.max, send -> cmd:SetTemperature, msgcnt:e2, flags:00, Cmd2id:40, src:MAX_123456 , dst:og.kinderzimmer.heizung , gid:00 , payload:67 , cul:none
2020.10.28 07:00:00 5 : cul.max, send packet: 0be2004012345615a6ac0067
2020.10.28 07:00:19 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:19 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 102, cul.maxcul CMD_LAST_H: 33
2020.10.28 07:00:19 2 : cul.max, cul.maxcul not enough credit! credit10ms is 102, but we need 110. Waiting 8 seconds. Currently 5 messages are waiting to be sent
2020.10.28 07:00:28 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:28 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 112, cul.maxcul CMD_LAST_H: 33
2020.10.28 07:00:28 4 : cul.max, Send Queue packet send : Zs0bf100401234561507380066 to og.arbeitszimmer.heizung with cul.maxcul
2020.10.28 07:00:29 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:30 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:30 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:31 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:31 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:32 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:00:32 3 : cul.max, Send Queue missing ack from og.arbeitszimmer.heizung for SetTemperature, removing from queue
2020.10.28 07:00:32 5 : cul.max, Send Queue 4 packets in queue
2020.10.28 07:00:32 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 6, cul.maxcul CMD_LAST_H: 33
2020.10.28 07:00:32 2 : cul.max, cul.maxcul not enough credit! credit10ms is 6, but we need 110. Waiting 104 seconds. Currently 4 messages are waiting to be sent
2020.10.28 07:01:48 5 : cul.max, BroadcastTime payload : 141c0781b0
2020.10.28 07:01:48 5 : cul.max, Broadcast time to 15a6ac
2020.10.28 07:01:48 4 : cul.max, send -> cmd:TimeInformation, msgcnt:e3, flags:04, Cmd2id:03, src:MAX_123456 , dst:og.kinderzimmer.heizung , gid:00 , payload:141c0781b0 , cul:none
2020.10.28 07:01:48 5 : cul.max, send packet: 0fe3040312345615a6ac00141c0781b0
2020.10.28 07:01:48 4 : cul.max, periodical TimeInformation sent to og.kinderzimmer.heizung
2020.10.28 07:02:17 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:02:17 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 111, cul.maxcul CMD_LAST_H: 33
2020.10.28 07:02:17 4 : cul.max, Send Queue packet send : Zs0b81004012345614100d0065 to eg.wohnzimmer.heizung.esszimmerfenster with cul.maxcul
2020.10.28 07:02:18 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:02:18 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:02:19 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:02:19 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:02:20 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:02:20 4 : cul.max, Send Queue retry eg.wohnzimmer.heizung.esszimmerfenster for SetTemperature count: 3
2020.10.28 07:02:23 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:02:23 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 8, cul.maxcul CMD_LAST_H: 33
2020.10.28 07:02:23 2 : cul.max, cul.maxcul not enough credit! credit10ms is 8, but we need 110. Waiting 102 seconds. Currently 5 messages are waiting to be sent
2020.10.28 07:04:07 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:07 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 111, cul.maxcul CMD_LAST_H: 33
2020.10.28 07:04:07 4 : cul.max, Send Queue packet send : Zs0b81004012345614100d0065 to eg.wohnzimmer.heizung.esszimmerfenster with cul.maxcul
2020.10.28 07:04:08 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:08 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:09 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:09 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:10 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:10 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:10 4 : cul.max, Send Queue retry eg.wohnzimmer.heizung.esszimmerfenster for SetTemperature count: 2
2020.10.28 07:04:13 5 : cul.max, Send Queue 5 packets in queue
2020.10.28 07:04:13 5 : cul.max, Send Queue cul.maxcul -> needPreamble: 1, necessaryCredit: 110, credit10ms: 8, cul.maxcul CMD_LAST_H: 33
2020.10.28 07:04:13 2 : cul.max, cul.maxcul not enough credit! credit10ms is 8, but we need 110. Waiting 102 seconds. Currently 5 messages are waiting to be sent

Wzut · 28 Oktober 2020, 07:18:09

Dein Problem hat starke Ähnlichkeit mit https://forum.fhem.de/index.php/topic,115314.0.html -> Stichwort initString.
Wobei bei dir der CUL durchaus MAX Telegramme empfängt -> Z0EAE020215A549123456000119001E04
aber weder der initString passt noch bei dir die Clients / MatchList.

Die Frage ist nun gab es in letzter Zeit Änderungen am 00_CUL Modul das deine und des anderen Users Merkwürdigkeiten erklären ?
Wie alt ist deine 00_CUL.pm bzw. wenn sie neu ist hast du noch eine ältere Version ?

cbl · 28 Oktober 2020, 07:51:32

Hallo,

die 00_CUL ist vom 16. Juni 2020. Da hat sich also "in letzter Zeit" nichts geändert.

Gruß
Christian

Wzut · 28 Oktober 2020, 08:02:55

stimmt, habe mir eben auf dem Testsystem via update die letzte 00_CUL.pm geholt.
Geh doch mal beim CUL auf Details und ändere den rfmode. Bei mir aktualisiert sich je nach Auswahl sofort die Client Liste.
Die muß bei rfmode MAX umspringen auf

Code Auswählen

:CUL_MAX:HMS:CUL_IR:STACKABLE_CC:TSSTACKED:STACKABLE:

cbl · 28 Oktober 2020, 13:43:16

Hallo,

ich habe im CUL den rfmode auf einen anderen Wert gestellt und danach wieder auf MAX zurück geändert. Die Client Liste hat sich entsprechend korrigiert (war vorher anders) und jetzt auch nach 30 Minuten sieht es gut aus und ich bekommen Reading Updates in meinen Heizkörper Devices.

Danke für den Hinweis!

Gruß
Christian

Wzut · 28 Oktober 2020, 17:59:37

Bleibt halt nur die Frage offen wie so etwas überhaupt passieren kann und wie es nach einem FHEM Neustart aussieht.

cbl · 08 November 2020, 00:53:50

Hallo,

nach einem Neustart (zuvor hatte ich vor Tagen die Einstellungen gespeichert) steht der rfmode zwar weiterhin auf MAX, die Clients sehen aber wieder merkwürdig aus und die SendQueue leert sich auch nicht.
Nachdem ich erneut den rfmode umgestellt und wieder auf MAX gesetzt habe, läuft es wieder.

Wie werden die Clients bei einem Neustart ermittelt? Beim Ursprungsposting gab es ganz sicher keinen Neustart kurz vor dem Beginn des Hängenbleibens. Die Ursache da muss eine andere gewesen sein als heute der Neustart.

Gruß
Christian

Wzut · 08 November 2020, 07:10:52

00_CUL.pm liegt in der Hand von Rudi, ich selbst habe mich mit dem Modul recht wenig beschäftigt.
D.h. ich bin da eigentlich auch nur User, was einem aber nie hindern sollte ruhig der älteren Dame mal unter den Rock zu schauen

Mal schauen ob ich den Automatismus verstehe der hinter der Umschaltung der Client Liste steckt beim setzen/wechseln des rfmodes.

Ich könnte jetzt natürlich auch in 14_CUL_MAX die bestehende Prüfung auf den richtigen rfmode erweitern und die Client Liste mit prüfen,
aber IMHO gehört diese Punkt ins 00_CUL Modul. Ich bin kein Freund von Symptomen behandeln statt der Ursache.

Wzut · 08 November 2020, 08:08:00

ich habe mir das mal genau angeschaut und auch etwas hin und her getestet.
Die Umschaltung der Client/Match List findet statt sobald das 00_CUL Modul auf das Attribut rfmode trifft,
also i.d.R. direkt beim FHEM Neustart. Allerdings gibt es hier eine Bedingung die erfüllt sein muß :
Der CUL muß sich bereits gemeldet haben und das Internal CMDS muß ein "Z" im String haben (Z = MAX)

Meine Theorie bis jetzt :
Das Modul trifft beim Neustart auf das Attribut rfmode = MAX aber der CUL hat seine Init Infos noch nicht gesendet ( Timing Problem ? )
Das sollte sich aber im Log nachlesen lassen, hier mal ein Beispiel wie es richtig ist :

Code Auswählen

2020.11.08 07:53:16 3: Opening CUL device /dev/serial/by-id/usb-busware.de_CUL868-if00
2020.11.08 07:53:16 3: CUL: Possible commands: BbCFiAZEGMKUYRTVWXefmltux
2020.11.08 07:53:16 3: CUL device opened
2020.11.08 07:53:16 2: Switched CUL rfmode to MAX

man sieht open-> CMDS -> opened -> rfmode
liegt die Meldung Possible commands: BbCFiAZEGMKUYRTVWXefmltux nicht vor müsste laut Code in 00_CUL eine not supported Meldung erscheinen.

Kannst du bitte mal dein Log auf diesen Abschnitt checken wenn das Problem wieder auftritt ?