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

[Baxxy]

Also...
A: wenn das Programm nicht ausgeführt wird...

Code: Alles auswählen

Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_GET"=0.000000 [execute():iseXmlRpc.cpp:321]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0.000000 [execute():iseXmlRpc.cpp:364]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_NUM"=0 [execute():iseXmlRpc.cpp:321]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0 [execute():iseXmlRpc.cpp:364]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_GET"=60.000000 [execute():iseXmlRpc.cpp:321]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 60.000000 [execute():iseXmlRpc.cpp:364]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_EVENT"=true [execute():iseXmlRpc.cpp:321]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."STATE"=true [execute():iseXmlRpc.cpp:321]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TS"="1646116873" [execute():iseXmlRpc.cpp:321]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1646116873 [execute():iseXmlRpc.cpp:364]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."WORKING"=true [execute():iseXmlRpc.cpp:321]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: called Program ID = 2145 'CUX_Timer_GET' with valNew = '0.000000' ; oidTrigger = 1870 [SetState():iseDOMPrg.cpp:483]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: type = DP_LESSOREQUAL, condition valL = 60.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:338]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1123]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, condition result = 0 [Evaluate():iseRule.cpp:235]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Rule evaluated state is FALSE by Program ID = 2145 'CUX_Timer_GET' [SetState():iseDOMPrg.cpp:536]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: wait max timeout = 240000 [ThreadFunction():iseRTEvent.cpp:69]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: called Program ID = 2145 'CUX_Timer_GET' with valNew = '60.000000' ; oidTrigger = 1870 [SetState():iseDOMPrg.cpp:483]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: type = DP_LESSOREQUAL, condition valL = 60.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:338]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1123]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, condition result = 0 [Evaluate():iseRule.cpp:235]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Rule evaluated state is FALSE by Program ID = 2145 'CUX_Timer_GET' [SetState():iseDOMPrg.cpp:536]

B: Wenn das Programm ausgeführt wird...

Code: Alles auswählen

Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_GET"=0.000000 [execute():iseXmlRpc.cpp:321]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0.000000 [execute():iseXmlRpc.cpp:364]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_NUM"=0 [execute():iseXmlRpc.cpp:321]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: called Program ID = 2145 'CUX_Timer_GET' with valNew = '0.000000' ; oidTrigger = 1870 [SetState():iseDOMPrg.cpp:483]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: type = DP_LESSOREQUAL, condition valL = 0.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:338]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, condition result = 1 [Evaluate():iseCondition.cpp:1123]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, condition result = 1 [Evaluate():iseRule.cpp:235]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: Rule evaluated state is TRUE by Program ID = 2145 'CUX_Timer_GET'; Destination ID = 2147 [SetState():iseDOMPrg.cpp:509]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Program ID = 2145 'CUX_Timer_GET', rule's trigger flags = 6 [SetState():iseDOMPrg.cpp:524]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: execute Program ID = 2145 'CUX_Timer_GET'; Destination ID = 2147 [Execute():iseDOMPrg.cpp:626]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: start execute Destination within the trigger delay 0 [Execute():iseDOMPrg.cpp:630]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: added element id=1861; oid=1861; val=Trigger registriert - Programm durchlaufen; time=0; oidTrigger=1870 [Add():iseRTScheduler.cpp:368]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: ExecuteDestination succeeded from Program ID = 2145 'CUX_Timer_GET' with valNew = '0.000000' [Execute():iseDOMPrg.cpp:640]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0 [execute():iseXmlRpc.cpp:364]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_GET"=60.000000 [execute():iseXmlRpc.cpp:321]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: calling SetState on DP id = 1861 (Programme_loggen) value = Trigger registriert - Programm durchlaufen oidTrigger = 1870 [ExecuteWriteJob():iseRTScheduler.cpp:636]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: SetState() succeeded for DP id = 1861 [ExecuteWriteJob():iseRTScheduler.cpp:641]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: ExecuteWriteJob: oid = 1861; ticks = 0 [Execute():iseRTScheduler.cpp:594]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: wait for event ms= 4294967295 [ThreadFunction():iseRTScheduler.cpp:484]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 60.000000 [execute():iseXmlRpc.cpp:364]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: called Program ID = 2145 'CUX_Timer_GET' with valNew = '60.000000' ; oidTrigger = 1870 [SetState():iseDOMPrg.cpp:483]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: type = DP_LESSOREQUAL, condition valL = 60.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:338]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1123]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, condition result = 0 [Evaluate():iseRule.cpp:235]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Rule evaluated state is FALSE by Program ID = 2145 'CUX_Timer_GET' [SetState():iseDOMPrg.cpp:536]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TIMER_EVENT"=true [execute():iseXmlRpc.cpp:321]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."STATE"=true [execute():iseXmlRpc.cpp:321]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."TS"="1646117593" [execute():iseXmlRpc.cpp:321]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1646117593 [execute():iseXmlRpc.cpp:364]
Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Event="CUX2800001:1"."WORKING"=true [execute():iseXmlRpc.cpp:321]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1864 [SetLastDPActionTime():iseDOMchn.h:288]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: call on change; id = 1862 [SetLastActionTime():iseDOMdev.h:225]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 1 [execute():iseXmlRpc.cpp:364]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: wait max timeout = 240000 [ThreadFunction():iseRTEvent.cpp:69]

Bei B findet man z.B.

Code: Alles auswählen

Mar  1 07:52:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Program ID = 2145 'CUX_Timer_GET', rule's trigger flags = 6 [SetState():iseDOMPrg.cpp:524]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: execute Program ID = 2145 'CUX_Timer_GET'; Destination ID = 2147 [Execute():iseDOMPrg.cpp:626]

Das fehlt bei A völlig.

[Baxxy]

Logauswertung:

Für mich sieht das weiterhin nach einem Timing-Problem oder "verschlucken" aus.

Bei A sieht die Bedingungsprüfung so aus...

Code: Alles auswählen

Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: called Program ID = 2145 'CUX_Timer_GET' with valNew = '0.000000' ; oidTrigger = 1870 [SetState():iseDOMPrg.cpp:483]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: type = DP_LESSOREQUAL, condition valL = 60.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:338]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, condition result = 0 [Evaluate():iseCondition.cpp:1123]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, condition result = 0 [Evaluate():iseRule.cpp:235]
Mar  1 07:40:13 RM-Test-OVA-18 local0.info ReGaHss: Info: Rule evaluated state is FALSE by Program ID = 2145 'CUX_Timer_GET' [SetState():iseDOMPrg.cpp:536]

Verbose: type = DP_LESSOREQUAL, condition valL = 60.000000 valR1 = 0.000000
Info: Rule evaluated state is FALSE
Damit ist klar das das DANN nicht ausgeführt wird.

Bei B:

Code: Alles auswählen

Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: called Program ID = 2145 'CUX_Timer_GET' with valNew = '0.000000' ; oidTrigger = 1870 [SetState():iseDOMPrg.cpp:483]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: type = DP_LESSOREQUAL, condition valL = 0.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:338]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseCondition.cpp:1121]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: sc = 0, condition result = 1 [Evaluate():iseCondition.cpp:1123]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, CONDITION_TRIGGER_TRUE is set. [Evaluate():iseRule.cpp:232]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: c = 0, condition result = 1 [Evaluate():iseRule.cpp:235]
Mar  1 07:52:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: Rule evaluated state is TRUE by Program ID = 2145 'CUX_Timer_GET'; Destination ID = 2147 [SetState():iseDOMPrg.cpp:509]

Verbose: type = DP_LESSOREQUAL, condition valL = 0.000000 valR1 = 0.000000
Verbose: Rule evaluated state is TRUE
Das DANN wird ausgeführt.

[uwe111]

Hallo Baxxy,

im Log ist mir folgendes aufgefallen:

Code: Alles auswählen

Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: called Program ID = 2145 'CUX_Timer_GET' with valNew = '0.000000' ; oidTrigger = 1870 [SetState():iseDOMPrg.cpp:483]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, trigger dp exists  [CheckCondition2Data():iseCondition.cpp:504]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: DP_VALUE_CHECK_UPDATE is set, condition = 1 [CheckCondition2Data():iseCondition.cpp:510]
Mar  1 07:40:13 RM-Test-OVA-18 local0.debug ReGaHss: Verbose: type = DP_LESSOREQUAL, condition valL = 60.000000 valR1 = 0.000000 [Evaluate():iseCondition.cpp:338]

Müsste im letzten Eintrag nicht type = DP_LESSOREQUAL, condition valL = 0.000000 valR1 = 0.000000 stehen, damit das ganze TRUE wird?

Viele Grüße

Uwe

[Baxxy]

Müsste im letzten Eintrag nicht...

Gute Frage,
ich bin da nicht so firm. So wie ich das verstehe müsste valL den Wert haben der bei

Code: Alles auswählen

called Program ID = 2145 'CUX_Timer_GET' with valNew = '0.000000'

übergeben wird.

Vielleicht kann @Black dazu was sagen.

Grüße, Baxxy

[Baxxy]

Das scheint tatsächlich irgendwie ein Timing Problem zu sein bzw. ist abhängig von der Leistungsfähigkeit der Hardware.

In die Riege der Testsysteme hat sich jetzt ein Pi1B mit RaspberryMatic 3.61.7.20220226 eingereiht.
Nach 10m Testzeit...
Pi1B: 0 Fails
CCU3: 3 Fails
OVA: 9 Fails

Grüße, Baxxy

[Gerti]

Hi!

Das ist vermutlich eher eine Race-Condition.
Das Programm wird bei/mit 0 durch den CUxD Timer getriggert.
Die Rega beginnt die Prüfung, aber der Timer steht mittlerweile wieder auf 60 (weil er von Neuem beginnt) und daher ist die Bedingung falsch.
Hier müsste der CUxD den Timer länger bei 0 stehen lassen, bevor er wieder herunterzählt.

Das ist daher in meinen Augen erstmal kein wirklicher Fehler der Rega, sondern vermutlich einfach der Laufzeit und der Tatsache geschuldet, dass der Timer sofort neu gestartet wird. Hier würde vermutlich eine Pause von 1s und dann ein loszählen von 59s das Problem lösen.

Nimm eine Systemvariable vom Typ Logikwert und nenne die Test.
Dann schreibe zwei Programme, die jeweils auf diese Variable bei wahr triggern und die Variable "sofort" auf ist falsch setzen.
Wenn Du die Variable nun auf wahr setzt, werden beide Programme nacheinander gestartet und das erste setzt die Variable auf wahr, das zweite nicht mehr, da die Variable inzwischen schon wieder auf falsch steht.

PS: Ich nutze den CUxD Timer eigentlich auch für viele Auslösungen auf meiner CCU3 und kann bisher keine Aussetzer feststellen.

Gruß,
Gerti

[uwe111]

Das ist daher in meinen Augen erstmal kein wirklicher Fehler der Rega, sondern vermutlich einfach der Laufzeit und der Tatsache geschuldet, dass der Timer sofort neu gestartet wird. Hier würde vermutlich eine Pause von 1s und dann ein loszählen von 59s das Problem lösen.

Das mit dem Fehler kommt ganz darauf an, welche Reaktion man hier erwartet. Vielleicht sollte ich dann eher die Doku aktualisieren und von der Nutzung von TIMER_GET zum Triggern abraten. Es gibt ja alternative Datenpunkte beim CUxD-Timer (z.B. TIMER_EVENT, STATE, TIMER_NUM).
Vom logischen Ablauf ist es ja so, dass der Timer sofort beim Ablauf (also 0) wieder auf die Anfangswert (also 60) gesetzt wird. Und nicht erst 1s später.

Ich hätte eigentlich erwartet, dass die Programmverknüpfung auf den Wert triggert, auch wenn er nur ein paar Millisekunden gültig ist. Es scheint aber so zu sein, dass zuerst die Programmverknüpfung bei Wertänderung triggert, sich dann unmittelbar danach der Wert ändert, dann der Vergleich mit dem alten Wert fehlschlägt und dann nicht erneut getriggert wird.

Baxxy, wenn dieses Verhalten auf ReGa Seite nicht geändert werden kann/soll, müsstest Du einen anderen Datenpunkt zum Testen nehmen, der den Status nicht so schnell ändert (z.B. TIMER_EVENT, STATE, TIMER_NUM)

Viele Grüße

Uwe

[Black]

Das scheint tatsächlich irgendwie ein Timing Problem zu sein bzw. ist abhängig von der Leistungsfähigkeit der Hardware.

Genau diesen Effekt hatte ich auch gehabt beim Wechseln vom PI3 auf die OVA als vM auf NUC.

Eigentlich hab ichs auf einen Fehler beim Umzug von Arm (PI) auf OVA (X86) geschoben, gefixt hab ich durch EInsatz von Zeitprogrammen, danach lief es und ich hab nicht weiter nachgeguckt

Black

[Baxxy]

@Gerti
Schön erklärt, Danke!

Das deckt sich auch soweit mit meinen inzwischen gewonnenen Erkenntnissen.
Ich dachte eigentlich das der "Wert" des Triggers zur Prüfung herangezogen wird, also irgendwie zwischengespeichert wird, und nicht nach Triggerung des Programmes nochmal der Wert für die Prüfung "geholt" wird.
Ändert sich also der Wert zwischen Triggerung und Prüfung, dann entspricht das Ergebnis nicht zwingend dem was man erwartet.

Gut... und auch irgendwie schlecht.

Interessant finde ich das das die Problematik augenscheinlich mit der Leistung des Host-Systems skaliert.
Nach 2h Testlauf (jede Minute)...

Code: Alles auswählen

System | OK / Fail | OK-Rate
--------------------
Pi1B   | 120 / 120 | 100%
CCU3   | 114 / 120 | 95%
OVA    | 38  / 120 | 32%

@Uwe111
Das Problem kommt m.E. nur zum tragen wenn der Haken bei SYSTEM|REPEAT gesetzt ist.
Wenn man die Problematik kennt, dann kann man drauf hinweisen das man möglichst SYSTEM|REPEAT x nicht in Kombination mit Triggerung auf TIMER_GET nutzen sollte.
Wenn man einen sich wiederholenden Timer nutzen möchte könnte man als Workaround diesen einfach wieder durch TIMER_SET im Programm "neustarten". Nicht unbedingt elegant, aber nach einem kurzen Test funktional.

Was die ReGa angeht... mal schauen ob @jmaus dazu mal was sagt.

Grüße, Baxxy

[MichaelN]

Interessant finde ich das das die Problematik augenscheinlich mit der Leistung des Host-Systems skaliert

aber durchaus logisch