RaspberryMatic icon indicating copy to clipboard operation
RaspberryMatic copied to clipboard
verified publisher icon jens-maus

WebUI Programme reagieren unzuverlässig auf Events trotz korrekter Bedingungen

Open Baxxy13 opened this issue 4 years ago • 1 comments

Describe the issue you are experiencing

Thematisch das gleiche Problem wie in #1278

Einfach ausgedrückt, WebUI Programme werden bei Eintreffen der Events und korrekten Bedingungen sporadisch nicht ausgeführt. Die grob ermittelte Fehlerrate liegt hier bei ~50% und höher.

Describe the behavior you expected

Wenn die Bedingungen erfüllt sind sollten WebUI - Programme bei Eintreffen der Events korrekt ausgeführt werden.

Steps to reproduce the issue

  1. ein frisches RM-System aufsetzen, Plattform egal, Version egal
  2. CUxD installieren und rebooten
  3. ein CUxD Timer-Device anlegen ( Typ (28) System - Funktion: Timer)
  4. den ersten Timer-Device Kanal konfigurieren (z.B. SYSTEM|TIMER_PRESET :30 ; SYSTEM|REPEAT x) (siehe Screenshot unten)
  5. den ersten Timer-Device Kanal auf protokolliert stellen
  6. eine Systemvariable Typ: Text anlegen und diese auf protokolliert setzen
  7. ein einfaches WebUI-Programm anlegen (nach CUxD-Handbuch Vorgabe mit TIMER_GET <= 0 bei Aktualisierung) (siehe Screenshot unten)
  8. das Ganze laufen lassen und ab und zu das Systemprotokoll kontrollieren

What is the version this bug report is based on?

3.61.7.20220226 - Release

Which base platform are you running?

ova (Open Virtual Infrastructure)

Which HomeMatic/homematicIP radio module are you using?

HmIP-RFUSB

Anything in the logs that might be useful for us?

-

Additional information

  1. Timer-Device: CUxD-Timer_minütlich_neu
  2. Test-Programm: CUxD_Trigger_Test_Prg_RM
  3. Systemprotokoll (Auszug):
19:14:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072113
19:15:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072173
19:16:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s
19:16:13 | 28.02.2022 | Programme_loggen | Trigger registriert - Programm durchlaufen
19:16:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072233
19:17:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072293
19:18:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072353
19:19:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072413
19:20:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0
19:20:13 | 28.02.2022 | Programme_loggen | Trigger registriert - Programm durchlaufen
19:20:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072473
19:21:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072533
19:22:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072593
19:23:13 | 28.02.2022 | CUxD-Timer-Dev:1 - GET | unbekannte Meldung (TIMER_GET) 0.00s, unbekannte Meldung (TIMER_NUM) 0, unbekannte Meldung (TIMER_GET) 60.00s, unbekannte Meldung (TIMER_EVENT=TRUE), Schaltzustand: ein, unbekannte Meldung (TS) 1646072653
  1. Eventprotokoll (Auszug via Homematic-Manager):
2022-02-28 19:14:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:14:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:14:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:14:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:14:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072113
2022-02-28 19:14:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:14:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:14:44 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:15:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:15:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:15:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:15:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072173
2022-02-28 19:15:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:15:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:15:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:15:44 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:16:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:16:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:16:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:16:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:16:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072233
2022-02-28 19:16:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:16:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:16:44 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:17:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:17:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:17:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:17:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:17:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072293
2022-02-28 19:17:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:17:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:17:44 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:18:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:18:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:18:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:18:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072353
2022-02-28 19:18:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:18:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:18:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:18:45 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:19:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:19:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:19:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:19:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:19:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072413
2022-02-28 19:19:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:19:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:19:45 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:20:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:20:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:20:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:20:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:20:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072473
2022-02-28 19:20:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:20:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:20:45 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:21:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:21:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:21:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:21:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:21:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072533
2022-02-28 19:21:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:21:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:21:45 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:22:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0
2022-02-28 19:22:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:22:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:22:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:22:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072593
2022-02-28 19:22:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:22:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:22:45 | event |   | CENTRAL |   | PONG | nr
2022-02-28 19:23:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 0
2022-02-28 19:23:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_GET | 60
2022-02-28 19:23:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_EVENT | true
2022-02-28 19:23:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | STATE | true
2022-02-28 19:23:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TS | 1646072653
2022-02-28 19:23:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | WORKING | true
2022-02-28 19:23:12 | event | CUxD-Timer-Dev:1 - GET | CUX2800001 | 1 | TIMER_NUM | 0

Man kann Anhand des Systemprotokolls und der Homematic-Manager Ereignisliste sehen das die Events vom CUxD-Timer-Device sauber generiert werden und dem System zur Verfügung stehen. Einzig die gewünschte Reaktion durch das WebUI-Programm bleibt viel zu oft aus. CUxD als mögliche Fehlerquelle würde ich daher erstmal ganz nach hinten schieben.

Auf einer frischen CCU3 kann ich das genauso reproduzieren, es ist also kein RM-spezifisches Problem.

Im verlinkten Issue hatte ich ja die Theorie geäußert das es "zum Verschlucken von Events" kommt wenn derer zu viele gleichzeitig auftreten. Das könnte auch hier eine mögliche Ursache sein.

Außerdem ist mir aufgefallen das das Problem nicht auftritt wenn ich... statt auf... TIMER_GET (FLOAT) <= 0.0 bei Aktualisierung auf TIMER_NUM (INTEGER) >= 0 bei Aktualisierung oder auf STATE (BOOL) = EIN bei Aktualisierung ...triggere.

Siehe auch: Link Homematik Forum

Baxxy13 avatar Feb 28 '22 18:02 Baxxy13

Logikschicht "alles loggen" Logfiles:

A: keine Ausführung des Programmes

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: korrekte Ausführung des Programmes

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 Einträge die bei A völlig fehlen:

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]

Weitere Erkenntnisse: Die CCU3 hat weit weniger Aussetzer als die RM-OVA. "Gefühlt" werden die Aussetzer bei beiden Systemen weniger wenn man nicht auf der WebUI unterwegs ist

Auswertung:

A:

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.

B:

Verbose: type = DP_LESSOREQUAL, condition valL = 0.000000 valR1 = 0.000000
Verbose: Rule evaluated state is TRUE

Das DANN wird ausgeführt.

Baxxy13 avatar Mar 01 '22 07:03 Baxxy13