[cul_hm] probleme mit wakeup und/oder lazyConfig und/oder A112

[noansi]

Hallo Frank,

dort fehlt in zeile 3716 eine schliessende geschweifte klammer vor dem else.

Danke für den Hinweis, ich hab's in beiden korrigiert. Fällt leider nicht auf, wenn man's nicht testet.

wenn ich es richtig verstehe, sind diese änderungen noch nicht in cul_hm 24158, sondern in deiner version aus beitrag #18. gestern habe ich aber erst martins neueste version 24158 getestet.
demnach kann der wunsch ja nicht die ursache sein.

Doch, das hatte Martin schon mitbekommen und eingearbeitet.

ausserdem gibt es schwierigkeiten bei diesem sensor mit dem timing. entweder das autonome 8102, oder der nachfolgende A001 cmd.

Ich denke, der schläft recht früh wieder ein, sprich reagiert nicht angemessen auf 8102 mit längerer Wachsamkeit.

Kann man natürlich auch so interpretieren, dass CUL_HM zu spät seinen nächsten Request schickt.

Aber dann würde alles "Hallo Wach" Protokoll keinen Sinn machen. Nach 269ms oder 221ms schon wieder schlafen ist zu knapp. Eine der autonomen Wiederholungen sollte er noch mindestens aufschnappen können sollen, denke ich.

Gruß, Ansgar.

[noansi]

Hallo Frank,

ich hab jetzt mal im Anhang die Attribut IODev Ergänzung eingebaut.
Bitte teste mal, ob es was gebracht hat.

Wenn Du das Attribut händisch setzt, dann kommt die Meldung: 'IODev handled'
Das ist kein Fehler, sondern hindert fhem.pl daran, am $hash->{IODev} Änderungen vorzunehmen.
Meist wird damit das IO direkt umgestellt, kann aber auch erst verzögert passieren, je nach Zustand.

Gruß, Ansgar.

[frank]

hallo ansgar,

ich hab jetzt mal im Anhang die Attribut IODev Ergänzung eingebaut.
Bitte teste mal, ob es was gebracht hat.

es hat zumindestens gezeigt, dass die definition meines cul in der fhem.cfg viel zu spät eingebaut war. 
eigentlich dachte ich gehört zu haben, dass die reihenfolge der definitionen nicht mehr so wichtig war.
oder war das vielleicht der grund, weshalb die anpassung des attr IODev irgendwann nicht mehr funktionierte?

alle probleme mit der wakeup-statusrequest-queue sind weiterhin identisch.



io zuweisung

ich hatte 2 neue meldungen nach restart im zusammenhang mit "IODev handled".

Code: [Auswählen]

2021.04.08 08:57:04.890 3: SwitchES01: unknown IODev cul868 specified
2021.04.08 08:57:06.387 3: test: unknown IODev cul868 specified
diese meldungen sind nachvollziehbar, da die definitionen der beiden devices vor der cul definition erfolgten und beide den cul als prefered io gesetzt hatten und zumindestens noch vor ein paar tagen der cul auch in attr IODev stand.


einige zeit nach restart sieht die ausgabe von "get vccu listDevice" so aus:

Code: [Auswählen]

devices using ccu
current IO / preferred
  cul868 / cul868 HM_196BD8
  cul868 / cul868 SwitchES01
  cul868 / cul868 SwitchPBU07
  cul868 / cul868 SwitchPBU08
  cul868 / cul868 SwitchPBU09
  cul868 / cul868 rssi_hmuart
  cul868 / hmlan1 DimUP01
  cul868 / hmlan1 SwitchUP02
  hmlan1 / hmlan1 DimPBU01
  hmlan1 / hmlan1 Fenster.Bad
  hmlan1 / hmlan1 SD.AZ
  hmlan1 / hmlan1 SD.SZ
  hmlan1 / hmlan1 SD.WZ
  hmlan1 / hmlan1 SDTeam
  hmlan1 / hmlan1 SwitchPBU01
  hmlan1 / hmlan1 SwitchPBU03
  hmlan1 / hmlan1 SwitchPBU04
  hmlan1 / hmlan1 SwitchPBU06
  hmlan1 / hmlan1 SwitchPL01
  hmlan1 / hmlan1 SwitchPL02
  hmlan1 / hmlan1 SwitchUP01
  hmlan1 / hmlan1 Thermostat.Bad
  hmlan1 / hmlan1 Thermostat.Bad.OG
  hmlan1 / hmlan1 Thermostat.Kueche
  hmlan1 / hmlan1 Thermostat.OZ
  hmlan1 / hmlan1 Thermostat.WZ
  hmlan1 / hmlan1 Tuer.WZ.Terrasse
  hmlan1 / hmlan1 VentilControler.AZ.Nord
  hmlan1 / hmlan1 VentilControler.AZ.West
  hmlan1 / hmlan1 VentilControler.Bad
  hmlan1 / hmlan1 VentilControler.Kueche
  hmlan1 / hmlan1 VentilControler.SZ
  hmlan1 / hmlan1 VentilControler.WZ
  hmlan1 / hmlan1 ccu
  hmlan1 / hmlan1 virtAktorAlarmOff
  hmlan1 / hmlan1 virt_vd
  hmuart1 / hmuart1 HM_114B05
  hmuart1 / hmuart1 SwitchPBU02
  hmuart1 / hmuart1 SwitchPBU05
  hmuart1 / hmuart1 Thermostat.AZ
  hmuart1 / hmuart1 Thermostat.GZ
  hmuart1 / hmuart1 Thermostat.Keller
  hmuart1 / hmuart1 Thermostat.SZ
  hmuart1 / hmuart1 Tuer.SZ
  hmuart1 / hmuart1 Ventil.AZ.Nord
  hmuart1 / hmuart1 Ventil.AZ.West
  hmuart1 / hmuart1 Ventil.Bad
  hmuart1 / hmuart1 Ventil.Kueche
  hmuart1 / hmuart1 Ventil.SZ
  hmuart1 / hmuart1 Ventil.WZ
  hmuart1 / hmuart1 Wetter.Nord
  hmuart1 / hmuart1 Wetter.Sued
  hmusb1 / cul868 test

1. in dieser liste sollte man eigentlich keine ignored devices listen.

2. das device test hat jeweils attr ignore und dummy gesetzt.
das nun zugewiesene io hmusb1 hat ebenfalls attr dummy gesetzt.
wie kommt es dazu, dass dieses io gewählt wird, obwohl es nicht operabel ist?

Code: [Auswählen]

attr ccu IOList hmlan1,cul868,hmusb1,hmuart1
3. das popup "IODev handled" bei der attribut eingabe ist sehr verwirrend.
es macht den eindruck, dass nichts passiert ist. man kann unendlich oft eine eingabe machen und jedesmal kommt das popup. erst wenn nach der bestätigung des popup die detailseite neu geladen wird, ist der erfolg sichtbar.

zusätzlich werden nach dem editieren und speichern der fhem.cfg über edit files dutzende fehler "IODev handled" angezeigt. ich dachte zuerst, jetzt habe ich die datei zerschossen. war aber alles ok.
also auch einfach nicht beachten und weiter machen.

ausserdem tauchen alle "IODev handled" zeilen auf der startseite nach dem restart auf.
das wird sicher viele aufgeregte support anfragen im forum aufwerfen, oder?

Code: [Auswählen]

Messages collected while initializing FHEM:configfile: IODev handled
IODev handled
IODev handled
IODev handled
...
4. wenn in dieser version die option none bei prefferedIO in der vccu funktionieren sollte, was zumindestens den eindruck macht, dann müsste man auch noch hminfo configcheck anpassen, da sonst folgender fehler auftaucht:

Code: [Auswählen]

IOgrp: prefered IO undefined
    DimPBU01: ->none
    DimUP01: ->none
    SwitchUP02: ->none
5. schön wäre ein logeintrag, eventuell mit verbose 4 bei der vccu, aus dem ein io-wechsel erkennbar wird.

6. irgendwie starten die automatischen statusrequests beim restart grundsätzlich sehr früh.
bei den ersten requests ist scheinbar nur der cul operabel, wodurch dieser zunächst alle msgs sendet.
der hmlan macht kurze zeit später dann auch mit.
der hmuart braucht noch länger um senden zu können.
damit alle prefferedIO die chance zum senden bekommen können, müsste der start der requests eigentlich um 3-5 sekunden verzögert werden.

mit der option none lässt sich dies zwar auch erreichen, aber dadurch wird der cul dann ja grundsätzlich als backup ausgeschlossen.


gruss frank

[noansi]

Hallo Frank,

alle probleme mit der wakeup-statusrequest-queue sind weiterhin identisch.

D.h.

2. der erste versuch des automatischen statusrequest nach fhem restart wird ohne autonome A112 ausgeführt.

das autonome senden von A112 findet nicht statt, da das io erst nach dem empfang der WAKEMEUP message entsprechend gesetzt wird.

Ist auch so geblieben? Ich hatte auch beim Attribut modelForce noch eine IO Aktualisierung ergänzt und gehofft, dass das noch was bringen könnte. -> OK, war Quatsch, hat aber auch nicht weh getan. Ich hab das wieder raus genommen.

eigentlich dachte ich gehört zu haben, dass die reihenfolge der definitionen nicht mehr so wichtig war.

Nun, nach Initialisierung von FHEM wird bei den devices die Konfiguration nochmal durchgeackert und ggf. ein IO gesetzt. Bis sich das aber alles "normalisiert" hat, können noch Probleme auftreten. Insbesondere, wenn messages vom IO vorher durch fhem verarbeitet werden sollten. Eigentlich sollten danach alle devices passend am IO angemedet sein.

das nun zugewiesene io hmusb1 hat ebenfalls attr dummy gesetzt.
wie kommt es dazu, dass dieses io gewählt wird, obwohl es nicht operabel ist?

Das sehe ich grundsätzlich als Bug im IO Modul, da es dann seinen XmitOpen auf 0 setzen sollte.
Eigentlich wird nur CUL anders behandelt und da würde das Problem auch auftreten. Wäre schön, wenn Rudolf auch XmitOpen einbauen würde.

3. das popup "IODev handled" bei der attribut eingabe ist sehr verwirrend.

Das hatte ich angekündigt. Wenn die attr IODev Behandlung was nützliches bringt, dann wäre es sicherlich möglich Rudolf zur einem Rückgabewert zu überzeugen, der in der fhem.pl schlicht ignoriert wird, oder eine andere Lösung. Dann fiellen die Meldungen weg.
Nur zum Testen geht es nicht anders, da das assignIO auch zu einem anderen IO schalten kann, als das Setzen des Attributes möchte, bei TSCUL z.B., wenn das IO auf dummy gesetzt wäre oder das IO aus anderem Grund nicht operabel anzeigt.
In jedem Fall müßtest Du im Vergleich feststellen, dass das Setzen des Attributes mit IO Wechsel auch meißt direkt zu einer IO Vorbereitung führt, was bisher nicht der Fall war.

5. schön wäre ein logeintrag, eventuell mit verbose 4 bei der vccu, aus dem ein io-wechsel erkennbar wird.

Wenn es mit der IO Zuweisung keine Probleme gibt, dann bin ich stark dafür das Logging weg zu lassen, sprich nur Log, wenn ein Fehler auftritt. Da es vor dem Senden ausgeführt wird, ist es zeitkrisch und der Logging String wird schon zusammen gebaut, bevor festgestellt wird, das der verbose level gar keinen Log Eintrag möchte.

damit alle prefferedIO die chance zum senden bekommen können, müsste der start der requests eigentlich um 3-5 sekunden verzögert werden.

Für meinen Geschmack eher noch deutlich mehr, weil auch andere Module (besonders bei mir ) via Timer noch mit verzögerten Startaktionen rechenzeitfordernd dazwischen funken. Statt Sekunden eher Minuten...

Gruß, Ansgar.

[frank]

hallo ansgar,


automatischer wakeup-statusrequest
das problem ist meiner meinung nach, dass die vorbereitung der aktion ebenfalls auf die WAKEMEUP message wartet.
es findet hier sozusagen keine trennung in "vorbereitung" und "ausführung" statt.

normaler weise wird ein befehl initiiert, indem der cmd einen logeintrag erhält, auf den stack kommt und das io präpariert wird. diese vorbereitung, gekennzeichnet durch cmds_pending, erwartet nun die aulösemessage.

nochmal aktuelles beispiel mit selbem device/IOdev:

Code: [Auswählen]

2021.04.08 18:37:31.126 4: CUL_Parse: cul868 A 0C 1B 8670 2064CB 000000 005B3FED -83.5
2021.04.08 18:37:31.130 3: CUL_HM set Thermostat.GZ_Climate statusRequest noArg
2021.04.08 18:37:31.243 0: HMUARTLGW hmuart1 recv: 01 05 00 00 4B msg: 1B 86 70 2064CB 000000 005B3F
2021.04.08 18:37:31.260 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:8B368ACB d:FF r:FFA5     m:1B 8670 2064CB 000000 005B3F
2021.04.08 18:37:31.341 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 1C A0 01 1ACE1F 2064CB 020E
2021.04.08 18:37:31.368 4: CUL_Parse: cul868 A 0B 1C A001 1ACE1F 2064CB 020E67 -22.5
2021.04.08 18:37:31.378 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:8B368BBD d:FF r:FFCD     m:1C A001 1ACE1F 2064CB 020E
2021.04.08 18:37:31.708 4: CUL_Parse: cul868 A 0B 1C A001 1ACE1F 2064CB 020E67 -22.5
2021.04.08 18:37:31.718 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:8B368D11 d:FF r:FFCD     m:1C A001 1ACE1F 2064CB 020E
2021.04.08 18:37:32.040 4: CUL_Parse: cul868 A 0B 1C A001 1ACE1F 2064CB 020E67 -22.5
2021.04.08 18:37:32.060 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:8B368E5B d:FF r:FFCD     m:1C A001 1ACE1F 2064CB 020E
2021.04.08 18:37:32.289 0: HMUARTLGW hmuart1 recv: 01 0404, state 100
2021.04.08 18:37:32.291 0: HMUARTLGW hmuart1 can't send due to unknown problem (no response?)
2021.04.08 18:37:32.292 0: HMUARTLGW hmuart1 send: 01 062064CB000100
2021.04.08 18:37:32.299 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 90
2021.04.08 18:37:32.300 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 90
2021.04.08 18:37:32.301 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.08 18:37:32.304 0: HMUARTLGW hmuart1 send: 01 062064CB000100
2021.04.08 18:37:32.310 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 93
2021.04.08 18:37:32.312 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 93
2021.04.08 18:37:32.312 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF

....

2021.04.08 18:40:14.633 4: CUL_Parse: cul868 A 0C 1C 8670 2064CB 000000 005C3FEC -84
2021.04.08 18:40:14.644 3: CUL_HM set Thermostat.GZ_Climate statusRequest noArg
2021.04.08 18:40:14.770 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 1D A0 01 1ACE1F 2064CB 020E
2021.04.08 18:40:14.774 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:8B390994 d:FF r:FFA5     m:1C 8670 2064CB 000000 005C3F
2021.04.08 18:40:14.777 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:8B390A0F d:FF r:FFCD     m:3C A112 1ACE1F 2064CB
2021.04.08 18:40:14.782 4: CUL_Parse: cul868 A 09 3C A112 1ACE1F 2064CB 67 -22.5
2021.04.08 18:40:14.788 0: HMUARTLGW hmuart1 recv: 01 0408, state 100
2021.04.08 18:40:14.789 0: HMUARTLGW hmuart1 IO currently busy, trying again in a bit
2021.04.08 18:40:14.842 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 1D A0 01 1ACE1F 2064CB 020E
2021.04.08 18:40:14.848 0: HMUARTLGW hmuart1 recv: 01 0408, state 100
2021.04.08 18:40:14.849 0: HMUARTLGW hmuart1 IO currently busy, trying again in a bit
2021.04.08 18:40:14.884 4: CUL_Parse: cul868 A 0A 3C 8002 2064CB 1ACE1F 00EE -83
2021.04.08 18:40:14.891 0: HMUARTLGW hmuart1 recv: 01 05 10 00 4B msg: 1C 86 70 2064CB 000000 005C3F
2021.04.08 18:40:14.898 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:8B390A92 d:FF r:FFA4     m:3C 8002 2064CB 1ACE1F 00
2021.04.08 18:40:14.986 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 1D A0 01 1ACE1F 2064CB 020E
2021.04.08 18:40:15.025 4: CUL_Parse: cul868 A 0B 1D A001 1ACE1F 2064CB 020E67 -22.5
2021.04.08 18:40:15.037 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:8B390B1E d:FF r:FFCD     m:1D A001 1ACE1F 2064CB 020E
2021.04.08 18:40:15.157 4: CUL_Parse: cul868 A 0E 1D 8002 2064CB 1ACE1F 01020C004FED -83.5
2021.04.08 18:40:15.176 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:8B390BA2 d:FF r:FFA4     m:1D 8002 2064CB 1ACE1F 01020C004F
2021.04.08 18:40:15.182 0: HMUARTLGW hmuart1 recv: 01 04 03 00 4B msg: 1D 80 02 2064CB 1ACE1F 01020C004F
2021.04.08 18:40:15.278 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 1E A0 01 1ACE1F 2064CB 020E
2021.04.08 18:40:15.306 4: CUL_Parse: cul868 A 0B 1E A001 1ACE1F 2064CB 020E67 -22.5
2021.04.08 18:40:15.315 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:8B390C37 d:FF r:FFCD     m:1E A001 1ACE1F 2064CB 020E
2021.04.08 18:40:15.438 4: CUL_Parse: cul868 A 0E 1E 8002 2064CB 1ACE1F 01020C0050EE -83
2021.04.08 18:40:15.533 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:8B390CBC d:FF r:FFA4     m:1E 8002 2064CB 1ACE1F 01020C0050
2021.04.08 18:40:15.537 0: HMUARTLGW hmuart1 recv: 01 04 03 00 4B msg: 1E 80 02 2064CB 1ACE1F 01020C0050
2021.04.08 18:40:15.540 0: HMUARTLGW hmuart1 send: 01 062064CB000000
2021.04.08 18:40:15.696 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 90
2021.04.08 18:40:15.697 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 90
2021.04.08 18:40:15.698 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.08 18:40:15.701 0: HMUARTLGW hmuart1 send: 01 062064CB000000
2021.04.08 18:40:15.714 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 93
2021.04.08 18:40:15.715 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 93
2021.04.08 18:40:15.716 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF


Das sehe ich grundsätzlich als Bug im IO Modul, da es dann seinen XmitOpen auf 0 setzen sollte.
Eigentlich wird nur CUL anders behandelt und da würde das Problem auch auftreten. Wäre schön, wenn Rudolf auch XmitOpen einbauen würde.

der hmusb hat xmitopen=0

Code: [Auswählen]

Internals:
   DEF        fritz.box:1234
   DeviceName fritz.box:1234
   FUUID      5c4ce2e7-f33f-09c4-37e6-608fb13c49ee601e
   NAME       hmusb1
   NR         28
   NTFY_ORDER 50-hmusb1
   STATE      disconnected
   TYPE       HMLAN
   XmitOpen   0
   assignedIDsCnt 0
   msgKeepAlive
   msgLoadCurrent 0
   owner     
   owner_CCU  ccu
   .attraggr:
   .attreocr:
     .*
   .attreour:
     prot_ERROR-Overload
     prot_Warning-HighLoad
     prot_disconnected
     prot_init
     prot_keepAlive
     prot_ok
     prot_timeout
   .attrminint:
   READINGS:
     2017-02-02 16:15:41   D-HMIdAssigned  1ACE1F
     2017-02-02 16:15:41   D-HMIdOriginal  263408
     2017-02-02 16:15:41   D-firmware      0.967
     2017-02-02 16:15:41   D-serialNr      KEQ1111271
     2021-04-09 23:17:18   Xmit-Events     dummy:1 disconnected:1
     2021-04-09 23:17:18   cond            dummy
     2017-02-06 11:11:46   loadLvl         low
     2021-04-09 23:17:18   prot_disconnected last
     2021-04-09 23:17:18   prot_dummy      last
     2017-02-06 23:17:13   prot_init       last
     2017-02-06 11:12:16   prot_keepAlive  last
     2017-02-02 16:15:41   prot_ok         last
     2017-02-02 09:47:45   prot_timeout    last
     2021-04-09 23:17:18   state           disconnected
   helper:
     assIdCnt   0
     assIdRep   0
     cnd:
       251        1
       253        1
     k:
       BufMin     30
       DlyMax     0
       Start      0
     loadLvl:
       bl         40
       a:
         99
         90
         40
         0
       h:
         0          low
         40         batchLevel
         90         high
         99         suspended
     log:
       all        0
       sys        0
       ids:
         20DFE1
     q:
       HMcndN     251
       answerPend 0
       hmLanQlen  1
       loadLastMax 0
       loadNo     0
       scnt       0
       ald:
         0
         0
         0
         0
         0
         0
         0
         0
         0
         0
         0
         0
       apIDs:
Attributes:
   dummy      1
   event-on-change-reading .*
   event-on-update-reading prot_ERROR-Overload,prot_Warning-HighLoad,prot_disconnected,prot_init,prot_keepAlive,prot_ok,prot_timeout
   group      IO-Devices
   hmId       1ACE1F
   hmLanQlen  1_min
   loadLevel  0:low,40:batchLevel,90:high,99:suspended
   logIDs     Thermostat.OZ
   room       90_Technik
   wdTimer    25

Das hatte ich angekündigt.

ich komme damit klar und es funktioniert auch gut, soweit es zu erkennen ist.

[noansi]

Hallo Frank,

das problem ist meiner meinung nach, dass die vorbereitung der aktion ebenfalls auf die WAKEMEUP message wartet.
es findet hier sozusagen keine trennung in "vorbereitung" und "ausführung" statt.

Du hast das Problem nur nach fhem restart, so habe ich es verstanden.
Beim nächsten ausgelösten statusRequest passiert es nicht mehr, richtig?

Mit dem push auf den leeren cmdstack wird das IO präpariert, allerdings nur, wenn die Information dazu vorliegen, dass das device es benötigt und es nicht bereits so vorbereitet ist. (so sagt es mir der code, glaube ich)

Code: [Auswählen]

sub CUL_HM_protState($$){
  my ($hash,$state) = @_;
  my $name = $hash->{NAME};

  my $sProcIn = $hash->{helper}{prt}{sProc};
  $sProcIn = 0 if(!defined $sProcIn);
...
  Log3 $name,5,"CUL_HM $name protEvent:$state".
            ($hash->{cmdStack}?" pending:".scalar @{$hash->{cmdStack}}:"");
  CUL_HM_hmInitMsgUpdt($hash) if (  $hash->{helper}{prt}{sProc} != $sProcIn
                                  && (   $hash->{helper}{prt}{sProc} < 2
                                      ||($hash->{helper}{prt}{sProc} == 2 && $sProcIn == 0 )));
}
Ich habe das Logging mal etwas erweitert (Anhang):

Code: [Auswählen]

  Log3 $name,5,"CUL_HM $name protEvent:$state".
            ($hash->{cmdStack}?" pending:".scalar @{$hash->{cmdStack}}:"")
            .", $sProcIn -> $hash->{helper}{prt}{sProc}, $hash->{helper}{io}{newChn}, $hash->{helper}{io}{rxt}";


der hmusb hat xmitopen=0

Wenn dummy nach der IO Zuweisung gesetzt wird, dann würde auch ein daraus resultierends XmitOpen=0 nicht helfen bis zum nächsten assignIO. Fällt mir zunächst dazu ein.
Ich habe zumindest noch einen Zusatzcheck für Wahl nach Attribut IODev eingebaut.

IODev Meldungen/Log habe ich zumindest ewas verringert.

Gruß, Ansgar.

Edit1: angepasst an 24214
Edit2: nun auch mit patch für unreachable letzter channel

[frank]

hallo ansgar,

Du hast das Problem nur nach fhem restart, so habe ich es verstanden.
Beim nächsten ausgelösten statusRequest passiert es nicht mehr, richtig?

wie in antwort #25 beschrieben, gibt es mindestens 3 probleme mit statusrequest.

nr2 kommt nur beim ersten versuch nach restart. hier wird der cmd zu "spät", nach dem empfang der WAKEMEUP msg, auf den leeren stack gepusht. dadurch wird natürlich kein A112 mehr gesendet.
man könnte auch sagen, dass das senden hier zu früh passiert, da das io ja gerade erst präpariert wurde.
präparieren des io und gleichzeitiges senden ist jedenfalls verkehrt.


hier ein sniff vom automatischen statusrequest nach restart.
der hat jetzt aus "versehen" funktioniert, ohne A112.

Code: [Auswählen]

2021.04.11 11:06:18.120 4: CUL_Parse: cul868 A 0C 14 8670 2064CB 000000 006C40EA -85
2021.04.11 11:06:18.123 3: CUL_HM set Thermostat.GZ_Climate statusRequest noArg
2021.04.11 11:06:18.124 5: CUL_HM Thermostat.GZ protEvent:CMDs_pending pending:1, 0 -> 2, +2064CB,00,00,00, 2
2021.04.11 11:06:18.124 0: HMUARTLGW hmuart1 send: 01 062064CB000100
2021.04.11 11:06:18.130 5: CUL_HM Thermostat.GZ protEvent:CMDs_processing... pending:0, 2 -> 1, +2064CB,02,00,00, 2
2021.04.11 11:06:18.158 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:06:18.162 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:06:18.165 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:990CFD9F d:FF r:FF9F     m:14 8670 2064CB 000000 006C40
2021.04.11 11:06:18.167 4: CUL_HM Thermostat.GZ dupe: dont process
2021.04.11 11:06:18.169 0: HMUARTLGW hmuart1 recv: 01 05 00 00 4B msg: 14 86 70 2064CB 000000 006C40
2021.04.11 11:06:18.170 4: CUL_HM Thermostat.GZ dupe: dont process
2021.04.11 11:06:18.172 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 90
2021.04.11 11:06:18.173 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 90
2021.04.11 11:06:18.173 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.11 11:06:18.176 0: HMUARTLGW hmuart1 send: 01 062064CB000100
2021.04.11 11:06:18.182 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 93
2021.04.11 11:06:18.183 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 93
2021.04.11 11:06:18.184 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.11 11:06:18.267 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 15 A0 01 1ACE1F 2064CB 020E
2021.04.11 11:06:18.292 4: CUL_Parse: cul868 A 0B 15 A001 1ACE1F 2064CB 020E67 -22.5
2021.04.11 11:06:18.303 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:990CFE4B d:FF r:FFCF     m:15 A001 1ACE1F 2064CB 020E
2021.04.11 11:06:18.425 4: CUL_Parse: cul868 A 0E 15 8002 2064CB 1ACE1F 01020C004FEA -85
2021.04.11 11:06:18.430 5: CUL_HM Thermostat.GZ protEvent:CMDs_done, 1 -> 0, +2064CB,02,00,00, 2
2021.04.11 11:06:18.453 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:06:18.457 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:06:18.460 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:990CFED0 d:FF r:FFA3     m:15 8002 2064CB 1ACE1F 01020C004F
2021.04.11 11:06:18.462 4: CUL_HM Thermostat.GZ dupe: dont process
2021.04.11 11:06:18.465 0: HMUARTLGW hmuart1 recv: 01 04 03 00 4B msg: 15 80 02 2064CB 1ACE1F 01020C004F
2021.04.11 11:06:18.466 4: CUL_HM Thermostat.GZ dupe: dont process
2021.04.11 11:06:18.468 0: HMUARTLGW hmuart1 send: 01 062064CB000000
2021.04.11 11:06:18.474 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 90
2021.04.11 11:06:18.475 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 90
2021.04.11 11:06:18.476 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.11 11:06:18.478 0: HMUARTLGW hmuart1 send: 01 062064CB000000
2021.04.11 11:06:18.485 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 93
2021.04.11 11:06:18.486 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 93
2021.04.11 11:06:18.486 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF


zum vergleich ein manueller statusrequest, der immer funktioniert.
in beitrag #25 beispiel nr1: es werden immer 2 cmds ausgeführt (ebenfalls beim restart):

Code: [Auswählen]

2021.04.11 11:03:27.536 3: CUL_HM set Thermostat.GZ_Climate statusRequest noArg
2021.04.11 11:03:27.561 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:27.584 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:27.586 5: CUL_HM Thermostat.GZ protEvent:CMDs_pending pending:1, 0 -> 2, +2064CB,00,00,00, 2
2021.04.11 11:03:27.588 0: HMUARTLGW hmuart1 send: 01 062064CB000100
2021.04.11 11:03:27.594 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 90
2021.04.11 11:03:27.596 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 90
2021.04.11 11:03:27.596 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.11 11:03:27.599 0: HMUARTLGW hmuart1 send: 01 062064CB000100
2021.04.11 11:03:27.726 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 93
2021.04.11 11:03:27.727 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 93
2021.04.11 11:03:27.727 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.11 11:03:28.127 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:28.155 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:28.882 0: HMUARTLGW hmuart1 send: 00 08
2021.04.11 11:03:28.886 0: HMUARTLGW hmuart1 recv: 00 040207, state 98
2021.04.11 11:03:28.888 0: HMUARTLGW hmuart1 GetSet Ack: 02, state 98
2021.04.11 11:03:28.888 0: HMUARTLGW hmuart1 roundtrip delay: 0.0034
2021.04.11 11:03:29.438 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:29.919 4: CUL_Parse: cul868 A 14 8D 805E 266EA5 1ACE1F 000000000000000000000025 -55.5
2021.04.11 11:03:29.928 0: HMLAN_Parse: hmlan1 R:E266EA5   stat:0000 t:990A6C7F d:FF r:FFCC     m:8D 805E 266EA5 1ACE1F 0000000000000000000000
2021.04.11 11:03:29.933 0: HMUARTLGW hmuart1 recv: 01 05 00 00 32 msg: 8D 80 5E 266EA5 1ACE1F 0000000000000000000000
2021.04.11 11:03:34.523 4: CUL_Parse: cul868 A 0C 68 8670 206278 000000 80A238EF -82.5
2021.04.11 11:03:34.710 0: HMUARTLGW hmuart1 recv: 01 05 00 00 4E msg: 68 86 70 206278 000000 80A238
2021.04.11 11:03:34.714 0: HMLAN_Parse: hmlan1 R:E206278   stat:0000 t:990A7E7B d:FF r:FFBB     m:68 8670 206278 000000 80A238
2021.04.11 11:03:39.997 4: CUL_Parse: cul868 A 0C B9 8670 206487 000000 006945F4 -80
2021.04.11 11:03:40.007 0: HMLAN_Parse: hmlan1 R:E206487   stat:0000 t:990A93DE d:FF r:FFB1     m:B9 8670 206487 000000 006945
2021.04.11 11:03:40.011 0: HMUARTLGW hmuart1 recv: 01 05 00 00 4B msg: B9 86 70 206487 000000 006945
2021.04.11 11:03:43.887 0: HMUARTLGW hmuart1 send: 00 08
2021.04.11 11:03:43.892 0: HMUARTLGW hmuart1 recv: 00 040207, state 98
2021.04.11 11:03:43.893 0: HMUARTLGW hmuart1 GetSet Ack: 02, state 98
2021.04.11 11:03:43.893 0: HMUARTLGW hmuart1 roundtrip delay: 0.0034
2021.04.11 11:03:44.090 0: HMLAN_Send:  hmlan1 I:K
2021.04.11 11:03:44.094 0: HMLAN_Parse: hmlan1 V:03C5 sNo:JEQ0315335 d:1C671E O:1ACE1F t:990AA3E1 IDcnt:0013 L:1 %
2021.04.11 11:03:47.117 4: CUL_Parse: cul868 A 0C 13 8670 2064CB 000000 006C40EB -84.5
2021.04.11 11:03:47.122 5: CUL_HM Thermostat.GZ protEvent:CMDs_processing... pending:0, 2 -> 1, +2064CB,02,00,00, 2
2021.04.11 11:03:47.146 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:47.150 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:47.153 0: HMLAN_Parse: hmlan1 R:E2064CB   stat:0000 t:990AAFAF d:FF r:FFA0     m:13 8670 2064CB 000000 006C40
2021.04.11 11:03:47.155 4: CUL_HM Thermostat.GZ dupe: dont process
2021.04.11 11:03:47.219 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 14 A0 01 1ACE1F 2064CB 020E
2021.04.11 11:03:47.225 0: HMUARTLGW hmuart1 recv: 01 0408, state 100
2021.04.11 11:03:47.226 0: HMUARTLGW hmuart1 IO currently busy, trying again in a bit
2021.04.11 11:03:47.239 4: CUL_Parse: cul868 A 09 2B A112 1ACE1F 2064CB 67 -22.5
2021.04.11 11:03:47.250 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:990AB02A d:FF r:FFCF     m:2B A112 1ACE1F 2064CB
2021.04.11 11:03:47.279 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 14 A0 01 1ACE1F 2064CB 020E
2021.04.11 11:03:47.285 0: HMUARTLGW hmuart1 recv: 01 0408, state 100
2021.04.11 11:03:47.286 0: HMUARTLGW hmuart1 IO currently busy, trying again in a bit
2021.04.11 11:03:47.338 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 14 A0 01 1ACE1F 2064CB 020E
2021.04.11 11:03:47.344 0: HMUARTLGW hmuart1 recv: 01 0408, state 100
2021.04.11 11:03:47.346 0: HMUARTLGW hmuart1 IO currently busy, trying again in a bit
2021.04.11 11:03:47.370 4: CUL_Parse: cul868 A 0A 2B 8002 2064CB 1ACE1F 00EB -84.5
2021.04.11 11:03:47.376 0: HMUARTLGW hmuart1 recv: 01 05 10 00 4B msg: 13 86 70 2064CB 000000 006C40
2021.04.11 11:03:47.473 0: HMUARTLGW hmuart1 send: 01 02 00 00 00 msg: 14 A0 01 1ACE1F 2064CB 020E
2021.04.11 11:03:47.511 4: CUL_Parse: cul868 A 0B 14 A001 1ACE1F 2064CB 020E67 -22.5
2021.04.11 11:03:47.521 0: HMLAN_Parse: hmlan1 R:E1ACE1F   stat:0000 t:990AB139 d:FF r:FFCF     m:14 A001 1ACE1F 2064CB 020E
2021.04.11 11:03:47.643 4: CUL_Parse: cul868 A 0E 14 8002 2064CB 1ACE1F 01020C004FEC -84
2021.04.11 11:03:47.648 5: CUL_HM Thermostat.GZ protEvent:CMDs_done, 1 -> 0, +2064CB,02,00,00, 2
2021.04.11 11:03:47.672 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:47.675 5: CUL_HM set Thermostat.GZ ?
2021.04.11 11:03:47.680 0: HMUARTLGW hmuart1 recv: 01 04 03 00 4B msg: 14 80 02 2064CB 1ACE1F 01020C004F
2021.04.11 11:03:47.682 4: CUL_HM Thermostat.GZ dupe: dont process
2021.04.11 11:03:47.683 0: HMUARTLGW hmuart1 send: 01 062064CB000000
2021.04.11 11:03:47.690 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 90
2021.04.11 11:03:47.691 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 90
2021.04.11 11:03:47.691 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF
2021.04.11 11:03:47.694 0: HMUARTLGW hmuart1 send: 01 062064CB000000
2021.04.11 11:03:47.700 0: HMUARTLGW hmuart1 recv: 01 04070101000EFFFFFFFFFFFFFFFF, state 93
2021.04.11 11:03:47.701 0: HMUARTLGW hmuart1 GetSet Ack: 07, state 93
2021.04.11 11:03:47.702 0: HMUARTLGW hmuart1 added peer: 2064CB, aesChannels: FFFFFFFFFFFFFFFF


[noansi]

Hallo Frank,

mit dem erweiterten Logging sieht man besser, was zu passieren scheint.

Code: [Auswählen]

2021.04.11 11:06:18.120 4: CUL_Parse: cul868 A 0C 14 8670 2064CB 000000 006C40EA -85CUL empfängt die Nachricht. Damit hat der HMUARTLGW diese auch schon empfangen.

Code: [Auswählen]

2021.04.11 11:06:18.123 3: CUL_HM set Thermostat.GZ_Climate statusRequest noArgHier wird ein statusRequest abgesetzt, da es gequeued wurde. Das pusht eine message auf den cmdstack. Davor gab es aber noch keinen statusRequest.
In der derzeit implementierten Logik hätte es einen geben müssen, damit das IO im Vorfeld vorbereitet wird (das wäre der erste der 2 statusRequest, die Dich beim manuellen statusRequest stören).

Code: [Auswählen]

2021.04.11 11:06:18.124 0: HMUARTLGW hmuart1 send: 01 062064CB000100
2021.04.11 11:06:18.130 5: CUL_HM Thermostat.GZ protEvent:CMDs_processing... pending:0, 2 -> 1, +2064CB,02,00,00, 2
HMUARTLGW wird vorbereitet (durch die message), hat auch alle Informationen dazu. Macht natürlich keinen Sinn mehr, weil er die Nachricht schon empfangen hat.

Damit ist für mich schon mal als wichtiger Punkt geklärt, dass alle Infos für das Vorbereiten des IOs bereit stehen, wenn der automatische statusRequest anläuft.
Der Rest wird komplizierter.

Warum ist der statusRequest gequeued ist die Frage? Ich denke die Antwort liegt im Delayed Status read.

Gruß, Ansgar.

[frank]

und martin hat vorhin auch ein neues update gemacht.

[noansi]

Hallo Frank,

ja, betrifft aber nicht dieses Problem hier.

Dafür die verbleibenden von #18 https://forum.fhem.de/index.php/topic,119853.msg1145485.html#msg1145485.

Auch IOgrp und "none".
Dein Hinweis zu HMInfo und "none" in IOgrp ist dabei noch nicht eingeschlossen gewesen. https://forum.fhem.de/index.php/topic,119853.msg1147382/topicseen.html#msg1147382 Punkt 4.
@Martin: kanst Du bitte mal da schauen.

Gruß, Ansgar.

[frank]

push