WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Anbindung von FS20-Komponenten, ELV-Wetterstationen, EnOcean und DMX an HomeMatic

Moderator: Co-Administratoren

Benutzeravatar
uwe111
Beiträge: 4819
Registriert: 26.02.2011, 22:22
Hat sich bedankt: 3 Mal
Danksagung erhalten: 245 Mal
Kontaktdaten:

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von uwe111 » 02.03.2022, 15:15

Baxxy hat geschrieben:
02.03.2022, 12:43
Also die Frage an Uwe...
Ließe sich das implementieren? Und wenn ja, würdest du dazu vielleicht mal eine Testversion erzeugen?
Ja, ist erledigt: http://cuxd.de/download/
Das 2. TIMER_GET Event sollte jetzt minimal später kommen.

Könntest Du bitte trotzdem einmal TIMER_EVENT als Trigger einer Programmverknüpfung loggen?
Dieser Datenpunkt ist eigentlich der richtige Trigger für die CUxD-Timer.
Vielleicht finden wir ja irgendetwas im Log?

Viele Grüße

Uwe
Alle sagten: Das geht nicht. Dann kam einer, der wußte das nicht und hat's einfach gemacht.
SPENDEN :wink: Download: CUxD 2.11, SSH KeyDir

Benutzeravatar
Baxxy
Beiträge: 10737
Registriert: 18.12.2018, 15:45
System: Alternative CCU (auf Basis OCCU)
Hat sich bedankt: 599 Mal
Danksagung erhalten: 2196 Mal

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von Baxxy » 02.03.2022, 15:21

uwe111 hat geschrieben:
02.03.2022, 15:15
ist erledigt:
Super, teste ich dann durch. Wie groß hast du die Verzögerung gemacht?
uwe111 hat geschrieben:
02.03.2022, 15:15
TIMER_EVENT als Trigger
Da sieht's aktuell ganz düster aus.
Weder der Pi1B noch die OVA reagieren darauf. Der Test läuft seit knapp ner Stunde.

Ich werde erstmal das Log begutachten.

Grüße, Baxxy

Benutzeravatar
Baxxy
Beiträge: 10737
Registriert: 18.12.2018, 15:45
System: Alternative CCU (auf Basis OCCU)
Hat sich bedankt: 599 Mal
Danksagung erhalten: 2196 Mal

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von Baxxy » 02.03.2022, 15:28

Protokoll der OVA:
Relevante Zeilen markiert.

Code: Alles auswählen

Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:2"."TIMER_GET"=0.000000 [execute():iseXmlRpc.cpp:321]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0.000000 [execute():iseXmlRpc.cpp:364]
Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:2"."TIMER_NUM"=0 [execute():iseXmlRpc.cpp:321]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0 [execute():iseXmlRpc.cpp:364]
Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:2"."TIMER_GET"=60.000000 [execute():iseXmlRpc.cpp:321]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 60.000000 [execute():iseXmlRpc.cpp:364]
--> Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:2"."TIMER_EVENT"=true [execute():iseXmlRpc.cpp:321]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:2"."STATE"=true [execute():iseXmlRpc.cpp:321]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: called Program ID = 1390 'CUxD_Timer_EVENT_Test' with valNew = '1' ; oidTrigger = 1056 [SetState():iseDOMPrg.cpp:483]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_CHANGE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:528]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: type = 1, condition valL = 1 valR1 = 1 [Evaluate():iseCondition.cpp:392]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_EXECUTE is reset. [Evaluate():iseCondition.cpp:1116]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, condition result = 1 [Evaluate():iseCondition.cpp:1123]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_EXECUTE is reset. [Evaluate():iseRule.cpp:227]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: c = 0, condition result = 1 [Evaluate():iseRule.cpp:235]
--> Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: Rule evaluated state is TRUE by Program ID = 1390 'CUxD_Timer_EVENT_Test'; Destination ID = 1392 [SetState():iseDOMPrg.cpp:509]
--> Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: break execute for Program ID = 1390 'CUxD_Timer_EVENT_Test', rule's trigger flags = 0 [SetState():iseDOMPrg.cpp:530]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:2"."TS"="1646230525" [execute():iseXmlRpc.cpp:321]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1646230525 [execute():iseXmlRpc.cpp:364]
Mar  2 15:14:25 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:2"."WORKING"=true [execute():iseXmlRpc.cpp:321]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1051 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 15:14:25 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Daraus werde ich erstmal nicht schlau...
Die Ausführung wird abgebrochen obwohl das Ergebnis TRUE ist?
"CONDITION_TRIGGER_EXECUTE is reset" klingt auch suspekt.

Grüße, Baxxy

Gerti
Beiträge: 3022
Registriert: 28.01.2016, 18:06
System: CCU
Wohnort: Hürth
Hat sich bedankt: 16 Mal
Danksagung erhalten: 268 Mal

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von Gerti » 02.03.2022, 16:30

Hi Uwe,
uwe111 hat geschrieben:
02.03.2022, 15:15
Das 2. TIMER_GET Event sollte jetzt minimal später kommen.
Wieviel Verzögerung ist drin?

Code: Alles auswählen

unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: Ein, unbekannte Meldung (TS) 1646234884, unbekannte Meldung (TIMER_GET) 300.00s
Im Logfile der CCU kommen die zumindest noch im selben Eintrag.
Ich weiß aber auch nicht, welchen Zeitraum das betrachtet.

Gruß,
Gerti

Benutzeravatar
Baxxy
Beiträge: 10737
Registriert: 18.12.2018, 15:45
System: Alternative CCU (auf Basis OCCU)
Hat sich bedankt: 599 Mal
Danksagung erhalten: 2196 Mal

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von Baxxy » 02.03.2022, 16:41

Das Logfile deckt m.E. nur ganze Sekundenbereiche ab.
Selbst wenn Uwe 50ms (sind es eher nicht :wink: ) drin hätte würde das vermutlich in einer Zeile stehen.

Also:
Kurzer Zwischenbericht zu TIMER_GET mit der 2.8.1 Testversion auf der OVA:

Das Verhalten hat sich drastisch verbessert.
Wo vorher quasi nur "Fails" waren muss man die jetzt "mit der Lupe suchen".
Bei aktuell 39 Triggerungen hatte ich nur einen Aussetzer.
Ich würde noch eine ms draufpacken. :)

Grüße, Baxxy

Edit:
Bei 60 Triggerungen nur 3 "Fails" (5%)
Gut, aber nicht perfekt.

Benutzeravatar
uwe111
Beiträge: 4819
Registriert: 26.02.2011, 22:22
Hat sich bedankt: 3 Mal
Danksagung erhalten: 245 Mal
Kontaktdaten:

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von uwe111 » 02.03.2022, 17:01

Baxxy hat geschrieben:
02.03.2022, 15:21
uwe111 hat geschrieben:
02.03.2022, 15:15
ist erledigt:
Super, teste ich dann durch. Wie groß hast du die Verzögerung gemacht?
Also vorher wurden alle Datenpunkte gesammelt und hintereinander in einem system.multicall übergeben. Jetzt habe das neue TIMER_GET da herausgelöst und sende es als extra Datenpaket ohne Verzögerung hinterher. Damit ist die zeitliche Reihenfolge m.E. eindeutig geklärt.

Könntest Du Jens davon ein SBK bereitstellen, damit er sich das und auch das TIMER_EVENT Problem mal genauer ansehen kann?
Ich bin eher dafür, dass das Problem beseitigt wird und gegen Workarounds, die dann andere Probleme verursachen.
Baxxy hat geschrieben:
02.03.2022, 16:41
Das Logfile deckt m.E. nur ganze Sekundenbereiche ab.
Selbst wenn Uwe 50ms (sind es eher nicht :wink: ) drin hätte würde das vermutlich in einer Zeile stehen.
Genau, selbst wenn ich es eine halbe Sekunde verzögern würde, dann sieht man es dort nicht. Aber man sieht, dass das neue TIMER_GET ganz am Ende steht.

Viele Grüße

Uwe
Alle sagten: Das geht nicht. Dann kam einer, der wußte das nicht und hat's einfach gemacht.
SPENDEN :wink: Download: CUxD 2.11, SSH KeyDir

Benutzeravatar
Baxxy
Beiträge: 10737
Registriert: 18.12.2018, 15:45
System: Alternative CCU (auf Basis OCCU)
Hat sich bedankt: 599 Mal
Danksagung erhalten: 2196 Mal

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von Baxxy » 02.03.2022, 17:12

uwe111 hat geschrieben:
02.03.2022, 17:01
als extra Datenpaket ohne Verzögerung hinterher. Damit ist die zeitliche Reihenfolge m.E. eindeutig geklärt.
Klappt ja schon ganz gut, aber eben (noch) nicht immer.
Hier mal einer der "Fails":

Code: Alles auswählen

Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_GET"=0.000000 [execute():iseXmlRpc.cpp:321]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0.000000 [execute():iseXmlRpc.cpp:364]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_NUM"=0 [execute():iseXmlRpc.cpp:321]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0 [execute():iseXmlRpc.cpp:364]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_EVENT"=true [execute():iseXmlRpc.cpp:321]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:1"."STATE"=true [execute():iseXmlRpc.cpp:321]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:1"."TS"="1646236275" [execute():iseXmlRpc.cpp:321]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1646236275 [execute():iseXmlRpc.cpp:364]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:1"."WORKING"=true [execute():iseXmlRpc.cpp:321]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_GET"=60.000000 [execute():iseXmlRpc.cpp:321]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1039 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: called Program ID = 1231 'CUxD_Timer_Get_Test' with valNew = '0.000000' ; oidTrigger = 1045 [SetState():iseDOMPrg.cpp:483]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: type = DP_EXACTVALUE, condition valL = 60.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:352]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1078]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1123]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: c = 0, condition result = 0 [Evaluate():iseRule.cpp:235]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: Rule evaluated state is TRUE by Program ID = 1231 'CUxD_Timer_Get_Test'; Destination ID = 1525 [SetState():iseDOMPrg.cpp:509]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Program ID = 1231 'CUxD_Timer_Get_Test', rule's trigger flags = 6 [SetState():iseDOMPrg.cpp:524]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: execute Program ID = 1231 'CUxD_Timer_Get_Test'; Destination ID = 1525 [Execute():iseDOMPrg.cpp:626]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: start execute Destination within the trigger delay 0 [Execute():iseDOMPrg.cpp:630]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: ExecuteDestination succeeded from Program ID = 1231 'CUxD_Timer_Get_Test' with valNew = '0.000000' [Execute():iseDOMPrg.cpp:640]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: call on change; id = 1037 [SetLastActionTime():iseDOMdev.h:225]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 60.000000 [execute():iseXmlRpc.cpp:364]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: wait max timeout = 240000 [ThreadFunction():iseRTEvent.cpp:69]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: called Program ID = 1231 'CUxD_Timer_Get_Test' with valNew = '60.000000' ; oidTrigger = 1045 [SetState():iseDOMPrg.cpp:483]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: type = DP_EXACTVALUE, condition valL = 60.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:352]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1078]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1123]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: c = 0, condition result = 0 [Evaluate():iseRule.cpp:235]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: Rule evaluated state is TRUE by Program ID = 1231 'CUxD_Timer_Get_Test'; Destination ID = 1525 [SetState():iseDOMPrg.cpp:509]
Mar  2 16:50:15 homematic-raspi local0.info ReGaHss: Info: Program ID = 1231 'CUxD_Timer_Get_Test', rule's trigger flags = 6 [SetState():iseDOMPrg.cpp:524]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: execute Program ID = 1231 'CUxD_Timer_Get_Test'; Destination ID = 1525 [Execute():iseDOMPrg.cpp:626]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: start execute Destination within the trigger delay 0 [Execute():iseDOMPrg.cpp:630]
Mar  2 16:50:15 homematic-raspi local0.debug ReGaHss: Verbose: ExecuteDestination succeeded from Program ID = 1231 'CUxD_Timer_Get_Test' with valNew = '60.000000' [Execute():iseDOMPrg.cpp:640]
Tesbackups für Jens kann ich dann bereitstellen.

Grüße, Baxxy

Gerti
Beiträge: 3022
Registriert: 28.01.2016, 18:06
System: CCU
Wohnort: Hürth
Hat sich bedankt: 16 Mal
Danksagung erhalten: 268 Mal

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von Gerti » 02.03.2022, 17:54

Hi!
uwe111 hat geschrieben:
02.03.2022, 17:01
Also vorher wurden alle Datenpunkte gesammelt und hintereinander in einem system.multicall übergeben. Jetzt habe das neue TIMER_GET da herausgelöst und sende es als extra Datenpaket ohne Verzögerung hinterher. Damit ist die zeitliche Reihenfolge m.E. eindeutig geklärt.
Die zeitliche Reihenfolge ist ja nicht das eigentliche Problem, sondern die Race-Condition die durch erneute Änderung des Wertes entsteht.
Dein erstes TIMER_GET löst die Triggerung aus, so dass die Rega die Bedingungen des Programms prüft.
Wenn zwischen diesem Auslösen und der eigentlichen Prüfung der Wert aber wieder geändert wird, schlägt diese Prüfung eben fehl.
Ich hatte das schon vor einigen Jahren bemerkt (mit den Systemvariablen, wie in meinem Beispielprogramm) und habe daher immer eine Pause von 1s eingebaut. Das hat bisher immer gereicht.
Wenn Der CUxD Timer nun ein Programm triggert, dass ggf. etwas länger zur Ausführung braucht und der Timer ggf. noch etwas anderes triggert, kann das auch jetzt noch immer scheitern, wenn der Zeitabstand zu gering wird.
Ich bleibe daher bei meiner Empfehlung, den Zustand 0 für 1s stehen zu lassen und dann mit dem neuen Timer um eine Sekunde verkürzt wieder zu beginnen. Damit sollte es eigentlich in allen Fällen zuverlässig funktionieren.

Gruß,
Gerti

Benutzeravatar
uwe111
Beiträge: 4819
Registriert: 26.02.2011, 22:22
Hat sich bedankt: 3 Mal
Danksagung erhalten: 245 Mal
Kontaktdaten:

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von uwe111 » 02.03.2022, 20:50

Hallo Gerti,
Gerti hat geschrieben:
02.03.2022, 17:54
Ich bleibe daher bei meiner Empfehlung, den Zustand 0 für 1s stehen zu lassen und dann mit dem neuen Timer um eine Sekunde verkürzt wieder zu beginnen. Damit sollte es eigentlich in allen Fällen zuverlässig funktionieren.
Ja, das ist bei mir aber erst Plan B, falls es Jens in der ReGa nicht hinbekommt. Ich finde es wichtiger, dass die ReGa die Events richtig verarbeitet. Das betrifft ja auch Events, die nicht vom CUxD kommen (dann leider nur nicht so gut reproduzierbar).
Aber das CUxD-Beispiel von Baxxy könnte Jens helfen, dieses Problem in der ReGa zu finden.

Viele Grüße

Uwe
Alle sagten: Das geht nicht. Dann kam einer, der wußte das nicht und hat's einfach gemacht.
SPENDEN :wink: Download: CUxD 2.11, SSH KeyDir

Gerti
Beiträge: 3022
Registriert: 28.01.2016, 18:06
System: CCU
Wohnort: Hürth
Hat sich bedankt: 16 Mal
Danksagung erhalten: 268 Mal

Re: WebUI-Programm triggert sporadisch nicht auf TIMER_GET <= 0 bei Aktualisierung

Beitrag von Gerti » 02.03.2022, 22:44

Hi,

ich kenne da eigentlich kein Problem mit der Rega, was nicht am Ende auf eben eine solche Race Condition hinausläuft.
Ich habe weit über 100 Zentralenprogramme, die völlig zuverlässig arbeiten.
Auch das Problem hier aus dem Thread, ist eben diese Race Condition, die ja grundsätzlich kein Fehler der Rega ist.
Ich hatte meine Gedanken dazu ja bereits geteilt, warum es eigentlich in der Rega keine Lösung dafür geben kann.
Selbst wenn Jens den Trigger mit einem gespeicherten Wert auswerten würde, würden Zusatzbedingungen dann wieder zum selben Verhalten führen und es wäre schlicht inkonsequent.

Gruß
Gerti

Antworten

Zurück zu „CUxD“