WebUI Programme reagieren unzuverlässig auf Änderungen von Sysvars welche via Scripten/State() verändert werden

jens-maus / RaspberryMatic

:house: A feature-rich but lightweight, buildroot-based Linux operating system alternative for your CloudFree CCU3/ELV-Charly 'homematicIP CCU' IoT smarthome central. Running as a pure virtual appliance (ProxmoxVE, Home Assistant, LXC, Docker/OCI, Kubernetes/K8s, etc.) on a dedicated embedded device (RaspberryPi, etc.) or generic x86/ARM hardware.

https://raspberrymatic.de

Apache License 2.0

1.52k stars 186 forks source link

WebUI Programme reagieren unzuverlässig auf Änderungen von Sysvars welche via Scripten/State() verändert werden #1278

Open WP-0461 opened 3 years ago

WP-0461 commented 3 years ago

Describe the bug

Es klingt unglaublich und ich würde es als IT-Projektleiter auch als nahezu unmöglich einstufen. Aber wie immer wieder im Job scheint mich nun auch hier eine unerwartbare Situation ereilt zu haben.

Nachdem ich in vielen Foren nicht fündig wurde aber nun nach drei Monaten mir sehr sicher bin einen Fehler gefunden zu haben, bitte ich um Prüfung / Reproduktion des Verhaltens sowie nach Möglichkeit nachfolgend um Fehlerbehebung. Meine Installation: Atuelles RasperryMatic auf Raspberry Pi 3+ (Charly) - 3.57.5.20210424 Anbindung über LAN an Iobroker mit tagesaktuellemmversionsstand ( 2021-05-18) 6 Thermostate und Fensterkontakten hmip 9 Rollladenaktoren hmip 2 Differenztemperaturfühler 3 Programme, welche mehrere Sysvar abhängig von Datum, Zeit, Temperatur etc. setzen (Nacht, schattieren, rollstatus, ….) Die Funktionalität dieser 3 Programme ist für mich stabil und durch logfiles (protokollierte Sysvars, Systemzustände, etc.) belegbar. Nun zum Problem: (mit und ohne aktive Verbindung zum iobroker) Alle Rolladenaktoren werden jeweils von jeweils einem eigenen auf die Sysvars reagierenden WebUI-Programm (9 Stück: alle vom gleichen kopiert nur bzgl. des zu steuernden Aktors abgewandelt) gesteuert. Auch die Reaktion dieser webui Programme lasse ich ins logfile (Sysvars aus welchen das durchlaufen der Programme ersichtlich wird) schreiben und sehe hier nachweislich „verlorene / vergessene Trigger“.

Die Sysvars „Rollnacht“ und „Rollnacht1“ werden von einem Script morgens und abends entsprechend gesetzt, hieraufhin sollten alle 8 webui Programme starten. Was sie auch bis Ende 2020 taten. Seit Updates Anfang 2021 werden einige der Programme nicht mehr gestartet. Dies ist an den protokollierten Sysvars eindeutig zu erkennen. Wird nachfolgend eine der zur Auslösung erforderlichen Sysvars „Rollnacht“ und „Rollnacht1“ manuell verändert, starten die webui Programme wie erwartet. Zwischenzeitlich wurden zunächst alle Programme manuell neu angelegt, die Hardware komplett erneuert, und heute wieder das System mittels eines frischen Images und einem aktuellen Backup neu aufgesetzt. Leider auch wieder ohne Erfolg.

Steps to reproduce the behavior

System mit meinem aktuellen Backup, einem Charly auf Basis RPI3+ aufsetzen und das Verhalten anhand der zu erwartenden Sysvars Protokollierungen in den schalt-Zeiträumen prüfen.
Der Fehler sollte nach Max 48 Stunden Laufzeit ersichtlich sein. Bei mir zeigt sich das Fehlverhalten täglich 2 mal.
Reproduktion ist evtl. auch in kürzeren Zeiträumen möglich, wenn die Zeiteinstellungen in den webui Programmen. Angepasst wird und zugleich eine Logik zum simulieren der Werte der schaltrelevanten Sysvar „SunEleRo“ erstellt wird.
...

Expected behavior Erwartet wird, dass alle 8 Programme („1-xxxxx“ bis „9-xxxx“) bei systemseitiger Änderung der Sysvar „Rollnacht“ und „Rollnacht1“ verlässlich gestartet werden.

Screenshots Backup liegt bei. logfiles stelle ich gerne bei Bedarf bereit ?

System information:

RaspberryMatic Version: ... 3.57.5.20210424
Used Hardware: ... Raspberry Pi 3+ (Charly) -
Used HomeMatic RF-Module: ...großes Charly funkmodul von elv von Anfang 2020.

Additional context Ich würde mich sehr über eine Kontaktaufnahme freuen.
Schöne Grüße W. Paduch

jens-maus commented 3 years ago

Erst einmal vorab: Also das von dir hochgeladene Backup deiner Zentrale hier habe ich vorsorglich mal gelöscht. Das war wirklich keine gute Idee dein komplettes Backup hier einfach so verbatim hochzuladen. Darin sind neben Passwörtern sicherheitsrelevante Dinge vermerkt. Sowas gehört nicht der Öffentlich preisgegeben. Damit hast du dein System zumindest nun zum Teil kompromittiert und du kannst nur hoffen das niemand anders das bereits runtergeladen hatte (wovon du eigentlich ausgehen musst!).

Abgesehen davon sehe ich nicht wie ich anhand der hier gegebenen Informationen irgendeinen Bug finden soll. Du gibst nur Symptombeschreibungen wieder und abgesehen vom unglücklich hochgeladenen Systembackup deiner Zentrale gehst du auf keinerlei technische Details ein oder zeigst screenshots, logfiles, etc.

Ich kann also anhand deiner Beschreibung hier nicht erkennen wo hier ein konkrekter Bug/Issue in RaspberryMatic vorliegen soll. Und auch dein Zentralenbackup hilft hier nicht weil man das nicht einfach so 1:1 selbst installieren kann ohne das deine Zentrale bei dir dann seine Arbeit einstellt (weil für die HmIP Geräte dann ein re-keying passiert sobald man das backup auf einer anderen Zentrale hochlädt). Bitte nutze die einschlägigen Diskussions- und Hilfeforen um zuerst dein Problem dort einem Expertenkreis vorzustellen und wenn sich aus dieser gemeinschaftlichen Diskussion dann konkrete Hinweise auf einen Bug/Issue (mit technischen Details) ergeben sollte kannst du gerne hier wieder ein Bug/Issue Ticket dazu aufmachen. Auch bitte beachten, dass GitHub kein Support-Forum ist und Bugs/Issues die hier gemeldet werden mit technischen details hinterlegt werden müssen um Nutzerprobleme (wie vmtl. bei dir) auszuschließen.

WP-0461 commented 3 years ago

Sorry Jens, aber im Alltag adressiere ich häufig Fehler und ermögliche das Nachstellen dieser. Das es hier mittels der bereitgestellten Daten nicht möglich sein soll kann ich nur auf Deinen sicherlich gut gemeinten Rat zum Thema Sicherheit zurückführen. Sei bitte versichert, dass ich die Zugangsdaten in diesem Datensatz zuvor anonymisiert hatte. Ich bin auch nicht der Meinung keine ausreichenden Screenshots oder logfiles bereitgestellt hatte, da ich erläutert hatte, das diese beim nachstellen erzeugt werden sollten. Aber gerne mache ich auch das noch wenn es uns hilft dieses sonderbare Verhalten zu ergründen. Von einem fehlerhaften Nutzerverhalten kann bei diesem Systemverhalten definitiv nicht ausgehen. Dein Vorschlag dies in Foren zu diskutieren finde ich in diesem Falle leider auch nicht zielführend, da wenn ich es auf das Funktionsprinzip beschränke, wird kein Fehler erkennbar sein. Lediglich in meiner Konfiguration mit den enthaltenen Scripts tritt der Fehler auf. Daher auch meine Bereitschaft Daten bereit zu stellen. Daher würde es mich freuen, wenn wir abseits der öffentlichen Diskussion einmal gemeinsam überlegen könnten wie wir dem Thema auf die Schliche kommen. Oder hast Du einen besseren Vorschlag als dass ich dann leider auf ein anderes System umsteigen muss ? Schöne Grüße Willi

jens-maus commented 3 years ago

Sei bitte versichert, dass ich die Zugangsdaten in diesem Datensatz zuvor anonymisiert hatte.

Hier geht es nicht nur um Nutzername+Passwort das du vielleicht in deinem Backup abgeändert hattest. In dem Backup finden sich z.B. Gerätedaten mit privaten Gerätekeys wieder und dadurch das du die jetzt öffentlich gemacht hattest sind die quasi kompromittiert. Damit ist es nun ein leichtes deine Geräte "zu übernehmen" oder einfach nur durch einspielen des Backups auf einer anderen Zentrale dir die HmIP Geräte unbrauchbar zu machen. Es war also definitiv die falsche herangehensweise ein Systembackup einer produktiven CCU komplett öffentlich zugänglich zu machen.

Ich bin auch nicht der Meinung keine ausreichenden Screenshots oder logfiles bereitgestellt hatte, da ich erläutert hatte, das diese beim nachstellen erzeugt werden sollten.

Eine CCU lässt sich nicht einfach 1:1 auf einer zweiten Zentrale betreiben wenn die Geräte nicht zur verfügung stehen oder eben durch das re-keying dann deine Geräte nicht mehr genutzt werden können. Also auch z.B. nicht einem Freund/Bekannten dein Backup geben damit er das mal testweise einspielen und versuchen kann die Probleme zu reproduzieren. Das würde in dem Falle dazu führen das deine HmIP Geräte zuhause dann nicht mehr (wenn auch nur zeitweise) funktionieren.

Aber lassen wir das jetzt hier. GitHub und vor allem dieses Issue Ticket hier ist wie gesagt kein Diskussionsforum. Verlagere das bitte in das HomeMatic Forum und diskutiere deine Probleme dort. Und wenn du ein problem hast, dann musst du das als erstes versuchen auf einer frischen/vanilla Installation noch einmal mit max 1-2 Geräten selbst nachzustellen. Und wenn du so dann einen reproduzierbaren Fall geschaffen hast lässt sich da vielleicht mal schauen was da schief geht. Und wenn es dann aber geht (wovon ich ausgehe) dann liegt der Fehler höchstwahrscheinlich in der Komplexität deiner Programmierung in der WebUI. Ein komplettes Backup einfach nur in den Raum zu werfen und zu hoffen jemand wird es schon reproduziert bekommen ist leider zu kurz gedacht, denn deine WebUI Programme werden ohne die Geräte (die nunmal bei dir zuhause stehen) nicht lauffähig sein.

WP-0461 commented 3 years ago

0k, vielen Dank Jens, nun soll’s hier auch gut sein. Ich verstehe nun, dass ich Fehlermeldungen hier bereits auf Detailfunktionen für einen Entwickler eingrenzen (lassen) muss. Um die mögliche Kompromittierung zu beseitigen reicht eine Neuinstallation auf Grundlage des Backups ? Oder sind alle Geräte neu anzulernen und die Programme über die Oberfläche neu einzubringen.

WP-0461 commented 3 years ago

Hallo Jens, nachdem ich diesen Text verfasst habe, habe ich mir meine Fehlerreproduktion nochmals angesehen mich nochmals meiner Erkenntnisse zu vergewissern. Daher nimm meine weiteren Ausführungen bitte als konstruktive Anregung auf.

Ich biete dir nochmals ein freundliches Telefonat / Screenchat o.ä. an, damit Du der nun von mir eingegrenzten Systemschwäche entgegentreten kannst. Die Wechselwirkung, welche ich nun in einer nackten neuen Installation in der Logik-Schicht ohne irgendwelche Geräte reproduzieren konnte möchte ich hier in Deinem Sinne zunächst wirklich nicht posten, es sei denn Du bittest mich darum.

Wenn Du keine Erklärung dafür hast, das 5 funktionierende Script-Zeilen (eines funktionierenden Scriptes von 40 Zeilen inkl. Kommentierungen, neben zwei weiteren Skripten) dazu führen, dass nur 1 bis 3 von 9 gleichen webui-Programmen richtig auf Änderungen von Systemvariablen reagieren sollte es uns möglich werden ein Gespräch zu vereinbaren.

In dieser Situation ist eigentlich davon auszugehen, dass die Verwendung von Skripten zu unvorhersehbarem Systemverhalten führt. Dies bedeutet dann aber für mich zugleich eine erhebliche Einschränkung des Funktionsumfangs und reduziertes Vertrauen in die Verlässlichkeit der RasperryMatic. Denn erfahrungsgemäß sind derartige Systemschwächen nur die Spitze eines Eisbergs da in diesen Fällen normalerweise nicht ausgeschlossen werden kann, dass sich die Ursache noch an weiteren Stellen auf die gesamte Systemfunktionalität auswirken kann. Und diese möchte ich nicht recherchieren und hier posten müssen.

Sollte ich mich wieder erwarten nach nun mehr als 8 Stunden Fehlereingrenzung irren, leiste ich hier gerne Abbitte und lasse Die einen Wein zukommen.

Schöne abendliche Grüße Willi

jens-maus commented 3 years ago

Wie bereits gesagt. Wenn du auf einer nackten Zentrale das nun (am besten ohne Geräteabhängigkeit) nachgestellt bekommst bin ich natürlich daran interessiert dem nachzugehen. Poste also bitte die besagten 5 Skriptzeilen (oder den gesamten Skript) von denen du annimmst das sie ursächlich sind. Dann kann ich mir das anschauen.

MichaelN0815 commented 3 years ago

Da bin ich mal sehr gespannt. Vermutlich .Variable() verwendet.

Baxxy13 commented 3 years ago

Auch die Reaktion dieser webui Programme lasse ich ins logfile (Sysvars aus welchen das durchlaufen der Programme ersichtlich wird) schreiben und sehe hier nachweislich „verlorene / vergessene Trigger“.

Was ist das für ein Logfile? Das Systemprotokoll? Die Logging-Funktion z.B. einer SysVar funktioniert nicht korrekt wenn zeitgleich mehrere Programme ihre Daten dort "ablegen".

Nach meinen Tests mit 7 zeitgleich ausgeführten Klonprogrammen wird immer nur der Wert des letzten Programms im Systemprotokoll angezeigt. Test_Klonprogramme Systemprotokoll: Test_Systemprotokoll_Klonprogramme Logge ich zusätzlich mit CUxD sieht man aber das alle Programme getriggert und ausgeführt wurden.

May 21 12:23:32 Test-CCU-RMatic-Pi3Bplus daemon.info cuxd[879]: CUX2801001:1 A_Test_SV_Trigger reagieren A 0
May 21 12:23:32 Test-CCU-RMatic-Pi3Bplus daemon.info cuxd[879]: CUX2801001:1 A_Test_SV_Trigger reagieren A 1
May 21 12:23:32 Test-CCU-RMatic-Pi3Bplus daemon.info cuxd[879]: CUX2801001:1 A_Test_SV_Trigger reagieren A 2
May 21 12:23:32 Test-CCU-RMatic-Pi3Bplus daemon.info cuxd[879]: CUX2801001:1 A_Test_SV_Trigger reagieren A 3
May 21 12:23:32 Test-CCU-RMatic-Pi3Bplus daemon.info cuxd[879]: CUX2801001:1 A_Test_SV_Trigger reagieren A 4
May 21 12:23:32 Test-CCU-RMatic-Pi3Bplus daemon.info cuxd[879]: CUX2801001:1 A_Test_SV_Trigger reagieren A 5
May 21 12:23:32 Test-CCU-RMatic-Pi3Bplus daemon.info cuxd[879]: CUX2801001:1 A_Test_SV_Trigger reagieren A 6

(mit CUxD geloggt wird über ein Einzeilerscript innerhalb des jeweiligen Programms) dom.GetObject("CUxD.CUX2801001:1.SYSLOG").State("A_Test_SV_Trigger reagieren A x");

Die Trigger-SysVar ist in meinem Testfall vom Typ "Logik" und wird durch ein zusätzliches Programm per Script... dom.GetObject (ID_SYSTEM_VARIABLES).Get ("SV_Logik").State(true); auf "WAHR" gesetzt.

Fazit des Test's:

Ich kann Stand jetzt keine Beeinträchtigung im Triggerverhalten von Programmen bei per Script gesetzten Systemvariablen feststellen.

WP-0461 commented 3 years ago

Halo Zusammen, danke für den Test. Tja, da wusste ich mit dem zwinkernden Hinweis .Variable() zunächst nichts anzufangen, da ich dies noch nie benutzt hatte und war zugegebenermaßen etwas verunsichert. Also kurz recherchiert und festgestellt, Fehlanzeige, ich arbeite schon immer mit .State()! Dennoch habe ich nochmal ca. 4 Stunden investiert sicher zu sein das ich Euch heute nicht wieder mit einer unglaublichen Trivialität nerve. Der Fehler ist in unterschiedlicher Intensität stabil bei mir reproduzierbar. Teilweise starten einige oder gar keine auf die Variable reagierende Programme. Aber die Variable, auf welche die Programme reagieren sollen ist nicht die, welche in meinen Skript-Zeilen bearbeitet wird. Die Variable welche die Programme auslösen soll wird in einem WebUI-Programm direkt gesetzt. - Sehr verwunderlich- oder ?

Vielleicht hilft es Euch doch, wenn ich Euch das Backup meines isolierten und frisch aufgesetzten RaspberryMatic Pi3B+ Testsystems zusätzlich zu den beigefügten Screenshots zukommen lasse.

Zudem befindet sich im Backup noch ein mini-WebIuProgramm welches Ihr beim Testen gerne mal zusätzlich zum toggeln der auslösenden Variablen aktivieren / reaktivieren könnt. Dann müsste Ihr wie ich sehen, dass über diesen Weg die Programme alle wie erwartet starten, nicht jedoch, wenn in einem anderen Programm zuvor die besagten Zeilen aktiv durchlaufen wurden. Sehr mysteriös.

Solltet Ihr zusätzlich zu den auf den Screenshots hinterlegten Kommentierungen noch weitere Erläuterungen wünschen, lasst es mich bitte wissen. Vorerst vielen Dank nochmals vorab.

Schöne Grüße Willi homematic-raspi-3.57.5.20210424-2021-05-21-1618.zip Screeshots.zip

PS.: Sollte es eine Liste der vom Skript-Interpreter angenommenen und ordnungsgemäß verarbeiteten Befehle/Methoden geben welche nicht zu verwenden sind, weil sie das System an anderer Stelle in unerklärliche "Schieflage" bringen, würde diese Zeilen dann sicher dort auftauchen, oder ?

MichaelN0815 commented 3 years ago

Also für jemanden, der von sich behauptet "im Alltag adressiere ich häufig Fehler und ermögliche das Nachstellen dieser" ist die Doku ziemlich unverdaulich aufbereitet. Skripte bitte nicht als Screenshot - wer will das abtippen? Und IIRC kann man Bilder auch direkt im Beitrag einbinden. ZIP runterladen, entpacken, boa.

Und dann sind die gezeigten Programme so komplex, das man das erstmal in gaaaaanz ruhiger Stunde analysieren muss. Geht es nicht eine Stufe weniger komplex? Meine Vermutung: dann tritt das "Problem" nciht mehr auf...

Wenn das WE verregt ist, werde ich es mir vielleicht nochmal vornehmen.

Aber einen Tipp habe ich noch: Skripte nicht alle 15 Sekunden aufrufen. Die WebUI ist kein Echtzeit-Betriebssystem und die Sonne rast ja auch nciht über den Himmel. Bei mir werden die Sonnenwinkel alle 3 Minuten berechnet und das reicht auch aus.

Und letzter EDIT für heute: was steht denn in Einstellungen/Systemsteuerung/Zentralen-Wartung/Logdatei an Fehlern bei der Skriptausführung?

WP-0461 commented 3 years ago

Danke dass Du es Dir nochmal vornehmen möchtest. Der 15 Sekunden Zyklus ist im Original natürlich wesentlich länger, aber möchtest Du beim Reproduzieren des Fehlers immer so lange warten ? Das war nur als Erleichterung zur Darstellung des Fehlers gedacht. Um Deine Frage zu beantworten, im Log finde ich keine Fehlermeldung, habe eben das System neu gestartet, den Fehler gesichtet und dann das aktuelles Log gezogen und angehangen.

Zuvor hatte ich mir aus den 3 verdächtigen Zeilen die Ergebnisse im Skripteditor nochmals ausgeben lassen. Die Ergebnisse der Statements entsprachen den Erwarteten aufgrund der Eingangswerte.

Was mich weiterhin an einen Fehler glauben lässt ist:

Keine Fehlermeldung im log
Keine Fehlermeldung im Skripteditor
Die Ergebnisse der Skriptverarbeitung im Editor sind wie erwartet
Die betroffenen Skriptteile haben keinen unmittelbaren Bezug zu der Variable, welche Webui-Programme auslösen soll
dennoch starten einige Programme nicht zuverlässig, welche von einer Variablen ausgelöst werden sollen, solange die 3 verdächtigen Zeilen zuvor ausgeführt wurden

Ja, das war auch für mich lange unverständlich und aus meiner Sicht lediglich durch Ansehen der Programme und Skripts fast schon unerklärlich. Aus diesem Grunde habe ich ab einem aus meiner Sicht ausreichenden Punkt aufgehört das Szenario weiter auszudünnen / zu vereinfachen. Und statt dessen zum Nachstellen (nicht zum Nachlesen) aus meiner bescheidenen Anforderungs-Sicht alles bereitgestellt, was ich bereitstellen kann, um das Verhalten aufwandsarm nachstellen zu können. Verzeih mir bitte wenn Du anderes erwartet hast.

Glaub mir, auch würde mich freuen, wenn ich falsch liege und Du und Alle anderen Experten feststellen, dass es kein Fehler sondern nur eine besondere Situation ist, welche evtl. bislang aus guten Gründen nicht betrachtet wurde.

Schöne Grüße und ein schönes erholsames Wochenende (es muss nicht verregnet sein und ich möchte auch nicht drängeln). ;-) Willi

homematic-raspi-2021-05-21 5.log

MichaelN0815 commented 3 years ago

Lade doch bitte noch das Skript als Text hoch. Danke.

WP-0461 commented 3 years ago

Bitteschön hier das Skript, hoffe nicht das durch Copy / Paste sich Zeichen verändert haben. Auf den ersten Blick sollte es passen. Gute Nacht, Danke Skript-1-SunPos 1.txt

MichaelN0815 commented 3 years ago

Hast Du die Programm #1 bis #9 über "Programme kopieren" erzeugt ODER jeweils neu zusammengeklickt? Das die Programme-kopieren-Funktion buggy ist (leider nciht reproduzierbar) ist bekannt. Dies führt häufig zu nicht reagierenden Progammen.

Warum führst Du das Skript 2 Sekunden verzögert aus?

Und ohne nochmals polemisch werden zu wollen, kann ich nur sagen, das ich persönlich zum Nachstellen von Fehlern das Problem möglichst weit vereinfache. Das kann ich Dir hier auch nur anraten. Ein Programm ohne SONST und SONST-WENN. Nicht mit 5-6 Bedingungen. So einfach wie möglich. Das schließt auch aus, das man irgendwo einen Haken in der Logik hat. Mal soll RA1 = 2 sein, mal größer 0. Ist mir zu komplex. Und ich sag Dir, das baut Dir kein Supporter der Welt nach. Weder die bezahlten, noch die freiwilligen. Und nochwas würde ich machen: CCU-Historian installieren; damit kannst Du bequem alle Daten analysieren. Und Alchys Auslöseskript. Dann kannst Du sehen, was WIRKLICH dein Programm ausgelöst hat. Die WebUI-Logik hat ihre Tücken. Debugging Tips: https://homematic-forum.de/forum/viewtopic.php?f=31&t=67597

Ich habe nochmal etwas experimentiert, aber der einzige Erkenntnissgewinn, den ich erreicht habe, ist das Du immer noch nciht klar dargestellt hast, wo der Fehler liegt. Du sagst, durch das Beschreiben der SV SunXXX wird RollNacht nicht mehr getriggert. Weil? Weil SunAz nicht mehr aktualisliert wird? Oder SunAz nicht mehr triggert? Oder why?

Du bist mit Deiner Analyse noch nicht fertig. Ich würde gerne im Log sehen, wie SunAz, RollNacht und die BsX aktualisiert werden. Meine Experimente zeugen, das alles nach Plan läuft. Vielleicht stolpern deine untereinander vernetzten Programme darüber, das die CCU die Sonnenwinkel nur 1x in der Minute neu berechnet, Du sie aber alle 15 Sek aufrufst. Oder weil Du Süd, West, Ost abfragst, was aber nicht zu deinem toggelnden Nacht passt.

Unbenannt

WP-0461 commented 3 years ago

Vielen Dank für Deine Bemühungen! Bin gerade etwas kurz angebunden, versuche aber dennoch einige Deiner Fragen zu beantworten, den Rest liefere ich dann gerne nach. Ich hatte dass System schon; einmal komplett neu zusammengeklickt, ohne erkennbaren Erfolg, schade. Hier in diesem Demo-Fall hatte ich es mir dann mittels der Kopierfunktion etwas einfacher gemacht. Damit ein Supporter nicht unbedingt alles nachbauen muss, hatte ich zuvor das Backup meines isolierten frisch aufgebauten Test-Systems bereitgestellt (Admin/Admin) . Dies in der Annahme, dass Jemand dieses Backup auf ein frisches Image zieht und die Reaktion der Variablen mit und ohne „Problemzeilen“ alleine schon in der Ansicht der Systemvariablen sehen kann. Die Variable, welche beschrieben werden, dienten in der Demo der Fehlversuche und dienten mir auf meinem produktiven System dazu im Systemprotkoll zu erkennen welches Programmteil angewendet wurde. Sonst wären die Programme ja leer.

Ich war bislang der Meinung, dass da die Programme ohne die Problemzeilen erwartungsgemäß laufen, ich an den #1 bis #9 Webu-Programmen nichts auszusetzen hatte und habe sie daher gar nicht mehr weiter analysiert.

Vor diesem Hintergrund nehme ich Deinen Vorschlag gerne auf und Click die 9 Programme nachher nochmals vereinfacht zusammen und bin gespannt was geschieht.

Die angesprochene Verzögerung von 2 Sek. VAR auch ein Test, bei dem ich meine erkannt zu haben, dass je nach Verzögerung sich des unerwartete Verhalten mehr oder weniger stark ausgeprägt war. Will heißen, zwischen einem und 8 nicht reagierende Programme.

Melde mich dann gerne nochmals

schönen Tag noch Willi

WP-0461 commented 3 years ago

Hallo @MichaelN0815, Phuu das waren nun wieder einige Stunden am Tablett und Rechner welche mir dann doch ein wenig den Haussegen beeinträchtigt haben. Im Ergebnis frage ich mich nun, wie ich Dir das Nachstellen der nun auch beim erneuten komplett manuell aufgesetzten raspberrymatic ersichtlichen Fehlers mit so wenig Aufwand wie möglich ermöglichen kann.

Folgendermaßen bin ich vorgegangen:

Neues Image auf sd-Card geflashed
Raspimatic gestartet und einige Sysvars angelegt (Bs1 bis Bs9 für den programmspezifischen Status und AAb übergreifend)
Neun Programme #1 bis #9 manuell angelegt mit einer „dann“ und „sonst“ Passage, welche von einer variablen „RollNacht“ bei Aktualisierungen ausgelöst werden soll und beim durchlaufen jeweils eine Variable “Bs1-9“ True / false setzt.
Ein Programm „P2SunNacht“ angelegt, welches auslöst wenn die Sysvar „SunAz“ aktualisiert wird. Dieses Programm toggelt beim durchlaufen die sysVariable „RollNacht“ True/false. Daraufhin sollten die 9 Programme auslösen und in den dann/sonst Passagen Variable setzten oder Geräte ansteuern. Geräte habe ich aus sicher verständlichen Gründen weggelassen.
Ein Programm „P1SunPos“ angelegt welches in festen Intervallen die angelegte sysVar „SunAz“ in einem Skript aktualisiert und im Skript nachfolgend die drei bekannten „Problemzeilen“ enthält.
Reboot der ccu
Da die Programme nun in den eingestellten Intervallen laufen sollten müssten sich in jedem Intervall die Inhalte der Variablen in der Variablen Ansicht der ccu wie erwartet ändern
Dies war dann auch der Fall. Also kein Fehler bis hier hin.
Also fügte ich in den 9 Programmen zwei weitere „Nur-Prüfungen“ der Variablen „RollSchatten“ und „SunOst“ in die erste Bedingung ein (wie es in meinem produktiven System erf. Ist).
Fehler tritt nach reboot immer noch nicht auf.
Ich ergänze alle 9 Programme um eine sonst/wenn Passage und lasse aus dieser dann auch wieder die Variablen „Bs1 bis Bs9“ und „AAb“ beschreiben.
Nun war, nach einem weiteren reboot das unerwartete, aus meiner Sicht fehlerhafte Verhalten an den Inhalten der Variablen in den triggerzyklen zu erkennen. Eben so wie auf meinem produktiv-System, wo ich mich seinerzeit zunächst nur über nicht wie erwartet reagierende Geräte wunderte, und dem Problem dann Mittels dieser „Status“-Variablen begann nachzugehen.
Dies prüfte ich noch drei mal inkl. reboots , dabei fiehl mir auf, dass ich, entgegen meiner Gewohnheit, im Skript eine Variable identisch mit der triggernden Sysvar „SunAz“ definiert hatte. Und schlimmer noch, diese taucht auch noch in den „Problemzeilen“ auf.
Also ändere ich die skriptvariable indem ich eine „1“ anhänge um Eindeutigkeit herzustellen.
Nun dachte schon darüber nach welche beiden Flaschen Wein ich aus dem Keller holen müsse.
Doch der nachfolgende Test, zeigte das gleiche Fehlerbild.

Nun habe ich hier also die minimalst konfigurierte ccu in welcher das Fehlverhalten beobachtet werden kann.

Was soll ich Dir / Euch nun zukommen lassen? Screenshots, und nochmals das nun neu getippte Skript als textfile ? oder reicht Euch aufwandsarm ein Backup um euch lästige tipperei zu ersparen ?

Aus heutiger Sicht kann ich, mangels Erfahrung/ Fähigkeit, keine weiteren Analysen durchführen. Bin aber natürlich gerne bereit mit eurer Unterstützung die nächsten Schritte zu gehen.

Ach ja, eine Verzögerung beim Skript wirkt sich nach meinen Beobachtungen weiterhin auf die Intensität des Fehlverhaltens aus.

Es ist sicherlich nicht mehr nachzuvollziehen, aber vor Jahren konnte ich beobachten, wie in einer „Nachbarabteilung“ eine Softwarekrise einem Fehler nachlief, welcher am Ende durch den Hersteller des Betriebssystems und nicht wie zu Beginn vermutet in den Applikationen gefixt wurde. Es hieß damals.: Systemtiming und Speichermanagement hätte angepasst werden müssen. Weis nicht ob das eine Idee ist.

Jetzt schalte ich für heute mal ab und wünsche noch frohe Pfingsten.

Danke ! Schöne Grüße Willi

MichaelN0815 commented 3 years ago

Was soll ich Dir / Euch nun zukommen lassen? Screenshots, und nochmals das nun neu getippte Skript als textfile ? oder reicht Euch aufwandsarm ein Backup um euch lästige tipperei zu ersparen ?

Mein Rat ist, das im Forum https://homematic-forum.de/forum/index.php zu untersuchen, da gibt es noch viel mehr know-how das bei der Analyse helfen kann. Hier ist der falsche Ort dafür.

Bitte mit Screenshots aller involvierten Programme, Auszug aus dem Log, das die Fehlfunktion belegt, Script in Code-Tags gepostet, damit man es weiter verarbeiten kann. EIn Backup werden die wenigsten in ihre CCU einspielen.

WP-0461 commented 3 years ago

Danke für Deinen Rat, Nun gibts es zwischenzeitlich schon eine weitere Erkenntnis. Ich habe festgestellt, dass anscheinend die weitere Ausführung eines ausgelösten Programms abbricht, wenn während der initialen „wenn-Prüfung“ eine der zu prüfenden Variablen von einem anderen Programm aktualisiert (nicht verändert) wird. Zumindest lassen die Ergebnisse der vermeintlich ausgelösten Programme im Systemprotokoll darauf schließen.

Aber ich kann das Thema nun auch gerne noch im Forum posten, oder möchtest Du nochmal drauf schauen ? Ich schreib dann gerne mal eine Abhandlung zur Reproduktion ohne Backup.

Schöne Grüße Willi

MichaelN0815 commented 3 years ago

Wenn du sehr viele Programme gleichzeitig startest und diese wiederum SV ändern, die für die BedingungPPrüfung benötigt werden, dann kann ich mir sehr gut vorstellen, dass dabei kein nachvollziehbares Ergebnis raus kommt. Dir wird ja auch klar sein, dass die Programme nicht wirklich gleichzeitig ablaufen können.

Zur weiteren Analyse empfehle ich immer nochddas forum. Letztlich hat Jens aber hier das "Hausrecht". AAber er hat sich ja auch dahingehend geäußert.

Baxxy13 commented 3 years ago

Ich habe das Demo-Setup mittels des angehängten Backups seit gestern Abend laufen. Den Zyklus hatte ich auf 59s erhöht und in jedes der 9 Programme noch kleine Loggerzeilen für CUxD eingebunden.

Auch hier treten in der Tat sporadisch Fehler bei der Ausführung der Programme auf. Das Demo-Setup ist ja so aufgebaut das immer abwechselnd alle 9 Programme in das 2.DANN (Nx - Nacht) bzw. in das 3.DANN (Tx - Tag) laufen müssen. Regulärer Lauf:

May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 SunAzi: 307.66 | SunAlt: -1.29
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T1
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T2
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T3
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T4
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T5
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T6
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T7
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T8
May 23 21:12:27 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T9
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 SunAzi: 307.86 | SunAlt: -1.41
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N1
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N2
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N3
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N4
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N5
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N6
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N7
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N8
May 23 21:13:26 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N9

Das klappt nicht 100% korrekt, es kommt immer mal wieder vor das die "hinteren" Programme (am häufigsten #9, dann seltener #8 und ganz selten #5 - #7) nicht geloggt / ausgeführt werden. Dadurch kommt es zur "Schiefstellung" der Programme und somit landen sie beim nächsten Lauf im SONST (Xx - Sonst). Fehlerhafter Lauf:

May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 SunAzi: 340.17 | SunAlt: -14.59
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T1
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T2
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T3
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T4
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T5
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T6
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T7
May 23 23:41:55 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 T8
<--- es fehlt T9
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 SunAzi: 340.40 | SunAlt: -14.64
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N1
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N2
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N3
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N4
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N5
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N6
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N7
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 N8
May 23 23:42:54 homematic-raspi daemon.info cuxd[756]: CUX2801001:1 X9 <--- Prg.9 geht ins SONST

Sauber reproduzieren kann ich das aber nicht. Dafür tritt es zu willkürlich auf. Grob überschlagen kam es in 6h Testzeitraum zu 15 "Nichtauslösungen" eines oder mehrerer Programme.

Es gab im Homematic-Forum schon mal den Fall das die Programmtriggerung durch mehrere gleichzeitig aktualisierende Systemvariablen nicht sauber funktionierte. Der Fall hier ist ja ähnlich gelagert. In dem Demo-Setup sind es zwar nur 2 gleichzeitig aktualisierende Systemvariablen pro Programm, das macht aber immerhin schon 18 Trigger zum gleichen Zeitpunkt. Mir fehlt aber das Fachwissen zur Logikschicht der Zentrale um sagen zu können das es hier zu Problemen kommen kann oder ob es generell irgendwelche Limits gibt.

Ich würde versuchen die einzelnen Trigger-Systemvariablen zeitlich etwas zu entzerren und diese auch nicht zu "aktualisieren" sondern tatsächlich nur bei geändertem Wert zu setzen. Bspw:

object sv_sun_ost = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("SunOst");
object sv_sun_sued = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("SunSued");
object sv_sun_west = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("SunWest");
 if (( (SunAzi >= SunOstS) == ( SunAzi < SunOstE )) && (!sv_sun_ost.Value())) { sv_sun_ost.State(true, 100)} else { if (sv_sun_ost.Value()) { sv_sun_ost.State(false, 100)}};
 if (( (SunAzi >= SunSuedS) == (SunAzi < SunSuedE)) && (!sv_sun_sued.Value())) { sv_sun_sued.State(true, 150) } else { if (sv_sun_sued.Value()) {sv_sun_sued.State(false, 150) }};
 if (( (SunAzi >= SunWestS) == (SunAzi < SunWestE)) && (!sv_sun_west.Value())) { sv_sun_west.State(true, 200) } else { if (sv_sun_west.Value()) {sv_sun_west.State(false, 200) }};

Grüße Baxxy

MichaelN0815 commented 3 years ago

Saubere Analyse! Wenn es da Limits gibt,sollte das Problem ja schlimmer werden, wwenn man es auf die Spitze treibt. Also noch mehr Programme oder Trigger erstellen...

Baxxy13 commented 3 years ago

In der "Demo" sind ja pro Programm nur 2 von 4 Systemvariablen als Trigger aktiv, kann mir schon vorstellen das das System noch mehr ins straucheln kommt wenn alle 4 aktiv sind (und möglicherweise gleichzeitig aktualisiert werden). Gerade gab es mal wieder einen "Doppelausfall" mit #8 und #9.

May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 SunAzi: 150.48 | SunAlt: 55.63
May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 T1
May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 T2
May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 T3
May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 T4
May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 T5
May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 T6
May 24 11:54:54 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 T7
<--- es fehlt T8
<--- es fehlt T9
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 SunAzi: 150.87 | SunAlt: 55.71
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 N1
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 N2
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 N3
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 N4
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 N5
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 N6
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 N7
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 X8 <--- Prg.8 geht ins SONST
May 24 11:55:53 homematic-raspi daemon.info cuxd[753]: CUX2801001:1 X9 <--- Prg.9 geht ins SONST

Ich lasse jetzt erstmal mit Delay (aber mit "Aktualisierung" der SV's) laufen und werde beobachten.

 if ( (SunAzi >= SunOstS) == ( SunAzi < SunOstE ) ) { dom.GetObject("SunOst").State(true, 100) } else {dom.GetObject("SunOst").State(false, 100) };
 if ( (SunAzi >= SunSuedS) == (SunAzi < SunSuedE) ) { dom.GetObject("SunSued").State(true, 150) } else {dom.GetObject("SunSued").State(false, 150) };
 if ( (SunAzi >= SunWestS) == (SunAzi < SunWestE) ) { dom.GetObject("SunWest").State(true, 200) } else {dom.GetObject("SunWest").State(false, 200) };

WP-0461 commented 3 years ago

Hallo @Baxxy13 Ich wollte die Diskussion meinerseits schon einstellen, freue mich nun, dass Du als ein hier wohl bekannter das Thema reproduzieren konntest. Vielen, vielen Dank !!

Daher stelle ich hier noch meine zwischenzeitlich stark vereinfachte Simulation bereit. Nur ein in Intervallen laufendes Skript „P1-View-ok“ welches die auslösevariable beschreibt und drei daraus reagierende Programme welche ihren Status in Sysvars sowie im sysprotokoll ablegen. ist diese Programm aktiv, kann hiermit das erwartete Verhalten beobachtet werden. Ist die manuell angelegte Kopie des „P1-View-Not-ok“ aktiv, ( in welchem sich ein Befehl zum zusätzlichem beschreiben einer zu prüfenden Variablen „Zusatz-Bedingung“ befindet) kann bei mir das unerwartete Verhalten schon nach wenigen Durchlaufzyklen an Variablen beobachtet werden. Die Variablen stehen natürlich alle zum nachvollziehen im Systemprotokoll.
Vielleicht hilft es ja es einem bekannten bug / Works-as-Designer Punkt zuzuordnen und hier zum Abschluss zu kommen.

Ich weiß mit dieser Situation nun umzugehen, denke aber, dass es gut wäre, wenn es sich als systemischer Problem bestätigt, die Situation zu fixen.

Euch Allen noch frohe Pfingsten Schöne Grüße Willi

homematic-raspi-3.57.5.20210424-2021-05-24-1245.zip

Baxxy13 commented 3 years ago

Ich gucke mir die neue vereinfachte Testumgebung dann demnächst noch an. Wenn das vereinfacht genug ist um auch auf original CCU3 zu laufen dann auch dort. (darf kein "nicht bei" enthalten). CCU3 und RM verwenden ja verschiedene ReGa-Versionen. Ich glaube zwar nicht das das ein RM-spezifisches Problem ist, aber so lässt sich das dann ausschließen.

Stand jetzt kann ich sagen das das von mir hinzugefügte Delay (200ms) für das setzen der SV "SunWest" (nur diese wird ja aktiv für die 9 Programme zusätzlich zur SV "RollNacht" genutzt) Wirkung zeigt. Im aktuell 3stündigen Testzeitraum gab es keine "Nichtauslösungen".

Das die ReGa der Zentrale nicht wirklich parallelisiert arbeitet ist ja bekannt. Daher muss es vermutlich für solchen zeitgleichen "Massenevents" einen Puffer geben. Ist der zu klein oder irgendwas stimmt damit nicht könnten Events "hinten runter fallen". So sieht das hier zumindest aus. Vielleicht kann ja @jens-maus zu den Abläufen ein bisschen Licht ins Dunkel bringen.

jens-maus commented 3 years ago

Vielleicht kann ja @jens-maus zu den Abläufen ein bisschen Licht ins Dunkel bringen.

Wenn das wirklich jetzt alles reproduzierbar ist und vielleicht sogar einfach ein backup/restore der regadom datei das ganze dann reproduzieren lässt kann ich mir das in einer ruhigen Minute gerne noch einmal detaillierter/genauer anschauen und versuchen eine Erklärung oder vielleicht sogar den Bug dahinter zu finden. Und wenn das soweit ist würde es wirklich helfen nochmal - wenn möglich - eine kurze Zusammenfassung zu geben so mit 5 punkteablaufplan oder so und dann kann ich das dann mit meiner limitierten Zeit gerne dann selbst mal nachstellen!

WP-0461 commented 3 years ago

Hallo @Baxxy13 Wie gewünscht anbei das Backup ohne „nicht bei“. Die Zykluszeit könntest Du ja wieder nach Deinem Ermessen einstellen. Interessant war im Lauf der letzten Stunden bei mir, dass lange gar keine Ergebnisse aus den Programmen protokolliert wurden, dann aber vereinzelt schon nach reboot in der letzten Stunde. Daher lege ich Dir das Systemprotokoll auch bei. Schöne Grüße Willi

homematic-raspi-3.57.5.20210424-2021-05-24-1656.zip History.csv

Baxxy13 commented 3 years ago

Alles klar, Danke. Mit dem Nachmittags-Backup kann ich das schon sauber reproduzieren. Auch wenn gefühlt manchmal etwas Willkür dabei ist. Übrigens reicht hier schon ein Delay von 1ms damit auch der Test mit "P1-View-nicht-ok" fehlerfrei läuft.

Ich gucke mir dann noch CCUx kompatible Version an lege die Ergebnisse dann hier nochmal strukturiert dar.

Baxxy13 commented 3 years ago

Mal ein Zwischenbericht...

Vorab:

Für mich ist das ganze kein Bug im eigentlichen Sinne, eher eine Systemschwäche die dann auftritt wenn 2 Events zeitgleich erzeugt werden, welche als Trigger für das gleiche Programm dienen
Es ist kein RM-spezifisches Problem. Mit einer CCU3 3.57.5 auf exakt der selben Hardware kann man das reproduzieren.
Mit älterer RaspberryMatic (Test mit 3.51.6.20200621) kann man es genauso reproduzieren
reproduzieren kann ich es nur wenn beide Systemvariablen als Trigger ("bei Änderung auslösen") dienen, steht die SV "Zusatz-Bedingung-1" auf "nur prüfen" läuft alles wie erwartet

Jetzt zur spekulativen Analyse:

SV "Zusatz-Bedingung-1" wird durch das Script zuerst aktualisiert --> die Programme wachen auf und die Bedingungsprüfung wird angestoßen
SV "Zusatz-Bedingung-1" wurde nicht geändert --> Programme legen sich schlafen
Theoretisch zeitgleich aber praktisch (vermutlich) minimal später wird SV "Angef-Status" geändert.
Die ReGa ist noch mit der obigen Prüfung beschäftigt, somit wird die Änderung nicht registriert und es passiert einfach nichts weiter

Als Ergebnis werden in ca. 95% der Triggerungen die Programme nicht ausgeführt. Zeitstempel ja, aber kein ausgeführtes DANN oder SONST. Ab und Zu kommt es aber zur korrekten Abarbeitung eines oder mehrerer Programme, das ist aber extrem zufällig.

Workarounds:

das Setzen der Systemvariablen innerhalb des Scriptes mit einem Delay versehen, schon 1ms reicht aus
das Script aufteilen und jeweils separat im WebUI-Programm ("P1-View-nicht-ok") einfügen, jedes Scriptchen kann auf "sofort" stehen, die Abarbeitung erfolgt trotzdem nacheinander
für dieses Testsetup reicht es sogar aus im Script innerhalb vom Programm "P1-View-nicht-ok" zuerst SV "Angef-Status" zu ändern und dann SV "Zusatz-Bedingung-1" zu aktualisieren. (Original ist die Reihenfolge andersherum)

Mein Fazit:

"wer zuerst kommt, mahlt zuerst..."

Zwei oder mehr quasi zeitgleiche Trigger kann die ReGa nicht verkraften. Da sie mit der Prüfung und Auswertung des zuerst eintretenden Events noch beschäftigt ist fällt das nachfolgende Event "hinten runter".

jens-maus commented 3 years ago

@Baxxy13 Danke für die kurze Zusammenfassung. Was ich allerdings bräuchte (um das nachzustellen) ist am besten eine fertige regadom datei die die programme inkl. skripte beinhaltet und die in einem frischen RaspberryMatic das sofort reproduzieren lässt.

Noch besser wäre natürlich wenn einfach Screenshots bzw. beschreibungen der benötigten WebUI Programme + Scriptausgaben hier das Problem einfach kurz noch einmal demonstriert werden könnte. Dann könnte ich das vielleicht einfach in das occu-test framework (https://github.com/jens-maus/occu-test) einbauen denn das testet ja quasi vollautomatisch die ReGaHss durch und man müsste das ja so nachstellen und entsprechend dann besser analysieren können als das jetzt auf einer vollwertigen Zentrale laufen lassen zu müssen. Nur so gäbe es dann eine reale Chance dieses runtime problem ggf. gefasst zu bekommen.

Baxxy13 commented 3 years ago

Kann ich die regadom einfach so rausziehen oder muss ich vorher was stoppen?

Das Testszenario ist quasi selbsterklärend.

3 Programme (#1; #2; #3)...
die auf 2 (zyklisch per Script innerhalb Programm "P1-View-nicht-ok") gesetzte Systmvariablen reagieren sollen
SV "Angef-Status" (Logik) wird im Wechsel auf true/false gestellt
SV "Zusatz-Bedingung-1" (Logik) wird zeitgleich (immer mit Status "false" aktualisiert)

! test script welches das ererwartete verhalten produziert
! sichtbar im systemprotokoll oder sicher mit anderen mitteln
! ebenfalls kann an den variablen schon beobachtet werde, das sie sich nicht wi erwartet alle ziemlich zeitgleich in den gleichen erwarteten zielstatus ändern.

!- setzen einer Systemvariablen (Logik), welche als Trigger ("bei Änderung auslösen") in den Programmen enthalten ist
dom.GetObject (ID_SYSTEM_VARIABLES).Get ("Zusatz-Bedingung-1").State(false);

integer delay = 1;  !- Delay zu Testzwecken; bei 0 werden die Programme nicht korrekt getriggert
object sv_angef_status = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("Angef-Status");

!- setzen einer Systemvariable (Logik), welche als Trigger ("bei Änderung auslösen") in den Programmen enthalten ist
!- Systemvariable toggelt im eingestellten (Zeitmodul) Intervall
if (sv_angef_status.Value()) {
    sv_angef_status.State(false, delay);
    system.Exec ("logger -t TRIGGERTEST -p user.debug SV Angef-Status getoggelt auf: false - Soll: 2.Dann - Test mit Delay: "#delay#" - Script");
    !dom.GetObject("CUxD.CUX2801001:1.SYSLOG").State("SV Angef-Status getoggelt auf: false | Soll: 2.Dann | Test mit Delay: "#delay);
}
else {
       sv_angef_status.State(true, delay);
       system.Exec ("logger -t TRIGGERTEST -p user.debug SV Angef-Status getoggelt auf: true - Soll: 1.Dann - Test mit Delay: "#delay#" - Script");
       !dom.GetObject("CUxD.CUX2801001:1.SYSLOG").State("SV Angef-Status getoggelt auf: true | Soll: 1.Dann | Test mit Delay: "#delay);
}

Ich habe überall Logger eingebaut weil ich kein Freund des Systemprotokolls bin. (System.Exec Logger ist aktiv; CUxD-Logger kann bei installiertem AddOn aktiviert werden)

Innerhalb des Scriptes in Programm "P1-View-nicht-ok" kannst du ein Delay "aktivieren". Ist hier ein Wert größer 0 drin sieht das Log folgendermaßen aus...

May 26 19:32:08 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: true - Soll: 1.Dann - Test mit Delay: 1 - Script
May 26 19:32:08 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr1-1.Dann
May 26 19:32:08 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr2-1.Dann
May 26 19:32:08 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr3-1.Dann
May 26 19:33:07 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: false - Soll: 2.Dann - Test mit Delay: 1 - Script
May 26 19:33:07 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr1-2.Dann
May 26 19:33:07 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr2-2.Dann
May 26 19:33:07 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr3-2.Dann

Hier führen die Programme korrekt jeweils das 1. oder 2. DANN je nach Status von SV "Angef-Status" aus.

Erwartet wird das die Programme genauso korrekt arbeiten wenn kein Delay im Script verwendet wird. Momentan sieht aber die Logausgabe dazu z.B. so aus:

May 26 19:18:22 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: true - Soll: 1.Dann - Test mit Delay: 0 - Script
May 26 19:19:21 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: false - Soll: 2.Dann - Test mit Delay: 0 - Script
May 26 19:19:21 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr1-2.Dann
May 26 19:20:20 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: true - Soll: 1.Dann - Test mit Delay: 0 - Script
May 26 19:21:19 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: false - Soll: 2.Dann - Test mit Delay: 0 - Script
May 26 19:22:18 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: true - Soll: 1.Dann - Test mit Delay: 0 - Script
May 26 19:23:17 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: false - Soll: 2.Dann - Test mit Delay: 0 - Script
May 26 19:24:16 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: true - Soll: 1.Dann - Test mit Delay: 0 - Script
May 26 19:24:16 homematic-raspi user.debug TRIGGERTEST: Aktivität-Progr1-1.Dann
May 26 19:25:15 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: false - Soll: 2.Dann - Test mit Delay: 0 - Script
May 26 19:26:14 homematic-raspi user.debug TRIGGERTEST: SV Angef-Status getoggelt auf: true - Soll: 1.Dann - Test mit Delay: 0 - Script

jens-maus commented 3 years ago

Kann ich die regadom einfach so rausziehen oder muss ich vorher was stoppen?

Du musst einfach vorher ReGaHss stoppen (z.B. monit stop regahss) und dann kannst du die regadom datei sicher wegkopieren. Und dann einfach mal auf einem frischen system genau die andere richtigung (regahss stoppen, regadom datei hinkopieren und dann rega wieder starten) und dann sollte das hoffentlich auch 1:1 reproduzierbar sein.

jens-maus commented 3 years ago

@Baxxy13

[...]
integer delay = 1;  !- Delay zu Testzwecken; bei 0 werden die Programme nicht korrekt getriggert
object sv_angef_status = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("Angef-Status");
[...]

Das ist in der Tat ein guter Hinweis und lässt bei mir ein paar "Glocken läuten", denn intern passiert beim Aufruf von State() mit und ohne Delay etwas substantiell anderes. Bei der Nutzung eines Delays beim Aufruf von State() wird das setzen des Wertes der Systemvariable nicht über den internen Eventmanager in ReGaHss selbst erledigt sondern wird direkt gemacht. Das könnte in der Tat die von dir und @WP-0461 bemerkten Probleme vielleicht erklären. Die Frage wäre ob du dieses komische Verhalten auch mit weniger komplexen WebUI Programmen bzw. mit einer geringeren Anzahl von WebUI Programmen reproduziert bekommst oder ist das was du da in diese 3 Programme gepackt hast definitiv notwendig um das Verhalten zu reproduzieren?

Baxxy13 commented 3 years ago

Gleiches Verhalten nach Einspielen der regadom auf einem frischen System (3.57.5.20210525 auf Pi3B) homematic.regadom.txt WebUI-PW: Admin SSH-PW: test

mit weniger komplexen WebUI Programmen bzw. mit einer geringeren Anzahl von WebUI Programmen reproduziert bekommst oder ist das was du da in diese 3 Programme gepackt hast definitiv notwendig um das Verhalten zu reproduzieren?

Na komplex ist doch was anderes. ;-) Aber nein, das Fehlverhalten tritt auch auf wenn nur ein einziges Programm auf die Trigger - SysVars reagieren soll.

MichaelN0815 commented 3 years ago

Ich kann dazu berichten, das ich in meine Anfangstagen auch Probleme mit nicht getriggerten Programmen hatte. Ich habe ein Skript, das Azimut und Elevation über die entsprechende Systemfunktion in 2 SV schreibt. Also "zeitgleich".

Ich hatte ein Programm, das beide SV als Trigger beinhaltete. Dieses Programm triggerte unzuverlässig "bei Änderung auslösen". Ging erst als ich auf "bei Aktualisierung" umgestellt habe. Heute habe ich keine Programme mehr, die Azimut UND Elevation als Trigger nutzen. Eins von beiden steht immer auf "prüfen". Das arbeitet rockstable.

Ich probiere mal aus, ob man das Verhalten auch so provozieren kann.

Baxxy13 commented 3 years ago

Bei der Nutzung eines Delays

Ich hatte das nur eingebaut um dem Fehler auf die Spur zu kommen. Wenn sv_angef_status.State(false, 0); anders arbeitet wie sv_angef_status.State(false); dann kannst du das auch entfernen. Bei mir war kein Unterschied zu merken, beide Varianten führten zu fehlerhaftem Verhalten.

MichaelN0815 commented 3 years ago

Ich lass das mal ein bisschen laufen, aber ich denke ich kann den Bug einfacher reproduzieren. Ich melde mich.

jens-maus commented 3 years ago

Wenn sv_angef_status.State(false, 0); anders arbeitet wie sv_angef_status.State(false); dann kannst du das auch entfernen.

Bei mir war kein Unterschied zu merken, beide Varianten führten zu fehlerhaftem Verhalten.

Nein, beide Varianten machen exakt das selbe. Erst wenn das delay > 0 ist wird intern das setzen der Systemvariablen bzw des Datenpunktes (man kann das State ja auch auf DP von Geräten anwenden) andes bzw über sen eventmanager erledigt wie das auch in webui programmen selbst der fall ist. Ist delay jedoch 0 oder eben nicht angegeben passiert das was bereits schon immer gemacht wird - der Datenpunkt bzw die Systemvariable wird direkt gesetzt.

Wenn ihr also testcases habt die wirklich stark simplifiziert sind (am besten ein webui programm mit wenigen bedingungen usw) dann am besten das so mal umsetzen, dann kann ich das in das testframework einbauen und schauen ob das den fehler auch zeigt.

MichaelN0815 commented 3 years ago

@Baxxy13 : wenn Du von "bei Änderung" auf "bei Aktualisierung" umstellst - tritt das Problem dann immer noch auf?

Ich bin ziemlich sicher, das Problem triff auf, wenn 2 SV "zeitgleich" per Skript geändert werden und ein Programm beide als Trigger "bei Änderung" abfragt. Mit "bei Aktualisierung" aber funktioniert es. Ich bastel morgen nochmal weiter an einen einfachen Test-Case. Jetzt muss ich hier Schluß machen, sonst sinkt mein persönlicher WAF zu stark...

Baxxy13 commented 3 years ago

Ich habe nun noch Alchy's Auslösescript integriert um zu sehen welche der beiden SVen das Programm triggerte.

Nutzt man "bei Aktualisierung" ergibt sich folgendes Bild:

Test ohne Delay

diejenige SV die im Programm auf "bei Aktualisierung" steht ist immer der Trigger, egal in welcher Reihenfolge die beiden SVen im Script gesetzt / aktualisiert werden
stellt man beide SVen auf "bei Aktualisierung" wird das Programm 2x getriggert, durch jede der beiden SVen einmal, in der Reihenfolge wie sie im Script gesetzt / aktualisiert werden

Test mit Delay

stellt man beide SVen auf "bei Aktualisierung" wird das Programm 2x getriggert, durch jede der beiden SVen einmal, die im Script gesetzte / aktualisierte SV mit Delay triggert erwartungsgemäß als zweites

Das ist zwar interessant hilft aber nicht wirklich weiter. Zumindest sieht man das es wohl doch kein "zeitgleich" gibt weil beide SVen "bei Aktualisierung" das Programm nacheinander triggern.

Somit bleibt meine Theorie das während der "Prüfung auf Änderung" des ersten Trigger-Events das zweite Trigger-Event verloren geht / ignoriert wird.

MichaelN0815 commented 3 years ago

Danke, das bestätigt meine Tests. Ist aber IMHO dahingehend wichtig, dass Änderung und Aktualisierung unterschiedlich behandelt werden. Der Zeitstempel wird bei meinen Versuchen übrigens immer aktualisiert, ees kommt nur nicht zur Ausführung.

Baxxy13 commented 3 years ago

Ich habe nun nochmal das Testsetup auf das absolute Minimum reduziert und es damit so simpel wie möglich gemacht.

2 Systemvariablen Typ Logik:

SV "Bedingung-A" wird im Script wechselweise auf true / false gesetzt
SV "Bedingung-B" wird im Script immer auf true gesetzt, also quasi "aktualisiert"

2 WebUI Programme:

Prg: "BX-Test-Aktion" wird per Zeitmodul zyklisch ausgeführt (alle 59s) und enthält nur das Script zum setzen der beiden SysVars

!- 1. setzen einer Systemvariable (Logik), welche als Trigger ("bei Änderung auslösen") im Programm enthalten ist
!- diese Systemvariable wird immer nur mit dem gleichen Status "aktualisiert"
dom.GetObject (ID_SYSTEM_VARIABLES).Get ("Bedingung-B").State(true);

integer delay = 0;  !- Delay zu Testzwecken; bei 0 wird das Programm zu ca. 95% nicht korrekt getriggert
object sv_bedingung_a = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("Bedingung-A");

!- 2. setzen einer Systemvariable (Logik), welche als Trigger ("bei Änderung auslösen") im Programm enthalten ist
!- Systemvariable toggelt im eingestellten (Zeitmodul) Intervall
if (!sv_bedingung_a.Value()) {
     sv_bedingung_a.State(true, delay);
     system.Exec ("logger -t TRIGGERTEST -p user.debug Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: "#delay);
}
else {
     sv_bedingung_a.State(false, delay);
     system.Exec ("logger -t TRIGGERTEST -p user.debug Script-Aktion: SV Bedingung-A auf: ist falsch - Sollergebnis-Prg: SONST - Delay: "#delay);
}
!- Als Ergenis müsste das Programm abwechselnd den DANN und SONST - Zweig ausführen

Prg: "BX-Test-Reaktion" soll durch die gesetzten SysVars korrekt triggern und muss abwechselnd im DANN / SONST landen

Die "Auswertung" erfolgt hier einzig durch Loggerscripte direkt ins Systemlog. Ich beobachte die Ergebnisse "live" per ssh mit tail -f /var/log/messages

Ein korrektes Ergebnis (nur mit gesetztem Delay möglich) sieht dann so aus.

May 27 16:26:17 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: 1
May 27 16:26:17 homematic-raspi user.debug TRIGGERTEST: Prog-Reaktion: Trigger-SV: Bedingung-A : ist wahr IST-Ergebnis: DANN
May 27 16:26:18 homematic-raspi user.debug TRIGGERTEST: X-------------------------------------------------------------------------------X
May 27 16:27:16 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist falsch - Sollergebnis-Prg: SONST - Delay: 1
May 27 16:27:16 homematic-raspi user.debug TRIGGERTEST: Prog-Reaktion: Trigger-SV: Bedingung-A : ist falsch IST-Ergebnis: SONST
May 27 16:27:17 homematic-raspi user.debug TRIGGERTEST: X-------------------------------------------------------------------------------X
May 27 16:28:15 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: 1
May 27 16:28:15 homematic-raspi user.debug TRIGGERTEST: Prog-Reaktion: Trigger-SV: Bedingung-A : ist wahr IST-Ergebnis: DANN
May 27 16:28:16 homematic-raspi user.debug TRIGGERTEST: X-------------------------------------------------------------------------------X
May 27 16:29:14 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist falsch - Sollergebnis-Prg: SONST - Delay: 1
May 27 16:29:14 homematic-raspi user.debug TRIGGERTEST: Prog-Reaktion: Trigger-SV: Bedingung-A : ist falsch IST-Ergebnis: SONST
May 27 16:29:15 homematic-raspi user.debug TRIGGERTEST: X-------------------------------------------------------------------------------X
May 27 16:30:13 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: 1
May 27 16:30:13 homematic-raspi user.debug TRIGGERTEST: Prog-Reaktion: Trigger-SV: Bedingung-A : ist wahr IST-Ergebnis: DANN
May 27 16:30:14 homematic-raspi user.debug TRIGGERTEST: X-------------------------------------------------------------------------------X

Ohne Delay holpert es vor sich hin, zu ca. 95% wird weder das DANN noch das SONST ausgeführt:

May 27 16:02:41 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 16:03:40 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 16:04:39 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 16:04:39 homematic-raspi user.debug TRIGGERTEST: Prog-Reaktion: Trigger-SV: Bedingung-A : ist wahr IST-Ergebnis: DANN
May 27 16:04:40 homematic-raspi user.debug TRIGGERTEST: X-------------------------------------------------------------------------------X
May 27 16:05:38 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 16:05:38 homematic-raspi user.debug TRIGGERTEST: Prog-Reaktion: Trigger-SV: Bedingung-A : ist falsch IST-Ergebnis: SONST
May 27 16:05:39 homematic-raspi user.debug TRIGGERTEST: X-------------------------------------------------------------------------------X
May 27 16:06:37 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 16:07:36 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 16:08:35 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 16:09:34 homematic-raspi user.debug TRIGGERTEST: Script-Aktion: SV Bedingung-A auf: ist falsch - Sollergebnis-Prg: SONST - Delay: 0

Hier noch die regadom dazu: homematic.regadom.txt WebUI-PW: Admin SSH-PW: test

Ich hoffe das reicht für den Debugger.

MichaelN0815 commented 3 years ago

Ich glaube das ist wirklich ein Timing Problem. Nachdem ich das heute auch mal sauber aufgebaut habe - ich habe übrigens fast die gleiche Systematik wie Du verwendet - kann ich den Fehler nicht mehr provozieren:

Systemvariablen: grafik

Programm zum 10 sekündigen tooglen: grafik

system.Exec ("logger -t xxxTest2 -p user.debug =============================================");

integer delay = 0;  !- Delay zu Testzwecken; bei 0 wird das Programm zu ca. 95% nicht korrekt getriggert
object sv_a = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("XXLogik");
object sv_b = dom.GetObject (ID_SYSTEM_VARIABLES).Get ("XXLogik2");

!- Systemvariable toggelt im eingestellten (Zeitmodul) Intervall
if (!sv_a.Value()) {
     sv_a.State(true, delay);
     sv_b.State(true, delay);
     system.Exec ("logger -t xxxTest2 -p user.debug Script-Aktion: SV A wahr - Sollergebnis-Prg: DANN - Delay: "#delay);
}
else {
     sv_a.State(false, delay);
     sv_b.State(true, delay);
     system.Exec ("logger -t xxxTest2 -p user.debug Script-Aktion: SV A falsch - Sollergebnis-Prg: SONST - Delay: "#delay);
}

ausgelöstes Programm: grafik

Ergebnis mit Delay 0: (Achtung: neuste Daten stehen oben)

May 27 19:56:40 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist falsch  um: 27.05. 19:56 Uhr
May 27 19:56:40 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - true
May 27 19:56:40 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 19:56:40 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:56:30 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 19:56 Uhr
May 27 19:56:30 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 19:56:30 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 19:56:30 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:56:20 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist falsch  um: 27.05. 19:56 Uhr
May 27 19:56:20 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - true
May 27 19:56:20 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 19:56:20 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:56:10 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 19:56 Uhr
May 27 19:56:10 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 19:56:10 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 19:56:10 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:56:00 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist falsch  um: 27.05. 19:56 Uhr
May 27 19:56:00 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - true
May 27 19:56:00 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 19:56:00 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:55:50 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 19:55 Uhr
May 27 19:55:50 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 19:55:50 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 19:55:50 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:55:40 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist falsch  um: 27.05. 19:55 Uhr
May 27 19:55:40 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - true
May 27 19:55:40 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 19:55:40 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:55:30 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik und dem Wert:ist wahr um: 27.05. 19:55 Uhr
May 27 19:55:30 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 19:55:30 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 19:55:30 ccu3-webui user.debug xxxTest2: =============================================

Ergebnis, wenn ich BEIDE SV toogle:

May 27 19:52:20 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist falsch  um: 27.05. 19:52 Uhr
May 27 19:52:20 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - false
May 27 19:52:20 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 19:52:20 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:52:10 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik2 und dem Wert:ist wahr  um: 27.05. 19:52 Uhr
May 27 19:52:10 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 19:52:10 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 19:52 Uhr
May 27 19:52:10 ccu3-webui user.debug xxxTest: SONST ausgeführt - true - true
May 27 19:52:10 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 19:52:10 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:52:00 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist falsch  um: 27.05. 19:52 Uhr
May 27 19:52:00 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - false
May 27 19:52:00 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 19:52:00 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:51:50 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik2 und dem Wert:ist wahr  um: 27.05. 19:51 Uhr
May 27 19:51:50 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 19:51:50 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 19:51 Uhr
May 27 19:51:50 ccu3-webui user.debug xxxTest: SONST ausgeführt - true - true
May 27 19:51:50 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 19:51:50 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:51:40 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist falsch  um: 27.05. 19:51 Uhr
May 27 19:51:40 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - false
May 27 19:51:40 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B falsch - Sollergebnis-Prg: SONST - Delay: 0
May 27 19:51:40 ccu3-webui user.debug xxxTest2: =============================================
May 27 19:51:30 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik2 und dem Wert:ist wahr  um: 27.05. 19:51 Uhr
May 27 19:51:30 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 19:51:30 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 19:51 Uhr
May 27 19:51:30 ccu3-webui user.debug xxxTest: SONST ausgeführt - true - true
May 27 19:51:30 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B wahr - Sollergebnis-Prg: DANN - Delay: 0
May 27 19:51:30 ccu3-webui user.debug xxxTest2: =============================================

Das Programm wird schon getriggert und ausgeführt, wenn nur die erste SV geändert wird. Dann wird es durch die Änderung der 2. SV nochmal getriggert!

Mit Delay 1 erst recht (aber das war auch zu erwarten)

May 27 20:08:50 ccu3-webui user.debug xxxTest2: =============================================
May 27 20:08:40 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik2 und dem Wert:ist wahr  um: 27.05. 20:08 Uhr
May 27 20:08:40 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 20:08:40 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 20:08 Uhr
May 27 20:08:40 ccu3-webui user.debug xxxTest: SONST ausgeführt - true - false
May 27 20:08:40 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B wahr - Sollergebnis-Prg: DANN - Delay: 1
May 27 20:08:40 ccu3-webui user.debug xxxTest2: =============================================
May 27 20:08:30 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist falsch  um: 27.05. 20:08 Uhr
May 27 20:08:30 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - false
May 27 20:08:30 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist falsch  um: 27.05. 20:08 Uhr
May 27 20:08:30 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - true
May 27 20:08:30 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B falsch - Sollergebnis-Prg: SONST - Delay: 1
May 27 20:08:30 ccu3-webui user.debug xxxTest2: =============================================
May 27 20:08:20 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik2 und dem Wert:ist wahr  um: 27.05. 20:08 Uhr
May 27 20:08:20 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 20:08:20 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 20:08 Uhr
May 27 20:08:20 ccu3-webui user.debug xxxTest: SONST ausgeführt - true - false
May 27 20:08:20 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B wahr - Sollergebnis-Prg: DANN - Delay: 1
May 27 20:08:20 ccu3-webui user.debug xxxTest2: =============================================
May 27 20:08:10 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist falsch  um: 27.05. 20:08 Uhr
May 27 20:08:10 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - false
May 27 20:08:10 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist falsch  um: 27.05. 20:08 Uhr
May 27 20:08:10 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - true
May 27 20:08:10 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B falsch - Sollergebnis-Prg: SONST - Delay: 1
May 27 20:08:10 ccu3-webui user.debug xxxTest2: =============================================
May 27 20:08:00 ccu3-webui user.debug xxxTest: *xxxTest*   DANN  durch Systemvariable: XXLogik2 und dem Wert:ist wahr  um: 27.05. 20:08 Uhr
May 27 20:08:00 ccu3-webui user.debug xxxTest: DANN ausgeführt - true - true
May 27 20:08:00 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik und dem Wert:ist wahr  um: 27.05. 20:08 Uhr
May 27 20:08:00 ccu3-webui user.debug xxxTest: SONST ausgeführt - true - false
May 27 20:08:00 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B wahr - Sollergebnis-Prg: DANN - Delay: 1
May 27 20:08:00 ccu3-webui user.debug xxxTest2: =============================================

Was habe ich denn jetzt anders gemacht, damit der Fehler nicht auftritt?

Baxxy13 commented 3 years ago

Hilfe... wo sind deine Code-Tags? ;-) Dreh mal an folgender Stelle in deinem Script die Reihenfolge um. aus...

sv_a.State(true, delay);
sv_b.State(true, delay);

mach...

sv_b.State(true, delay);
sv_a.State(true, delay);

Die Beobachtung hatte ich irgendwo auch schon gemacht, also das es sauber läuft wenn die sich nicht ändernde SV als zweites gesetzt wird.

MichaelN0815 commented 3 years ago

Hilfe... wo sind deine Code-Tags? ;-)

Keine Ahnung, die funktionieren bei mir nie Eingesetzt habe ich die,aber ohne Erfolg

jens-maus commented 3 years ago

Hilfe... wo sind deine Code-Tags? ;-)

Keine Ahnung, die funktionieren bei mir nie Eingesetzt habe ich die,aber ohne Erfolg

Die setzt man ja auch nicht mit den GUI buttons ein, die sind nur für Single-Line Codezeilen gedacht. Wenn du multi-line code hast dann muss du die in drei aufeinanderfolgende ` statt nur einem (also ```) einbetten. Keyboard und RTFM nutzen! ;-)

EDIT: So, hab dein Text mal angepasst. Mach mal selbst "editieren" und du solltest hoffentlich verstehen was zu machen ist damit in Zukunft deine GitHub Texte besser lesbar sind!

MichaelN0815 commented 3 years ago

Github hat echt ein Nerd programmiert.

Danke fürs korrigieren.

jens-maus commented 3 years ago

Github hat echt ein Nerd programmiert.

Na klar. Word, Windows und GUIs ist halt auch was für "Opfer" ;-)

MichaelN0815 commented 3 years ago

Dreh mal an folgender Stelle in deinem Script die Reihenfolge um.

Das hat auch noch keinen Effekt erzielt. Da ich aber beobachtet habe, das der SONST Zweig ausgeführt wird, obwohl dann im SONST-Zweig beide SV als WAHR ausgegeben werden, habe ich vermutet das eine der SV zum Zeitpunkt des Prüfens noch FALSE wahr und beim Skriptdurchlauf dann schon TRUE.

Daher habe ich nun die SV auf "nur prüfen" gesetzt die als 2. aktualisiert wird und siehe da - ein unerwartetes Verhalten tritt auf.

May 29 11:23:30 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist falsch  um: 29.05. 11:23 Uhr
May 29 11:23:30 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - false
May 29 11:23:30 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B falsch - Sollergebnis-Prg: SONST - Delay: 0
May 29 11:23:30 ccu3-webui user.debug xxxTest2: =============================================
May 29 11:23:20 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist wahr  um: 29.05. 11:23 Uhr
May 29 11:23:20 ccu3-webui user.debug xxxTest: SONST ausgeführt - true - true
May 29 11:23:20 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B wahr - Sollergebnis-Prg: DANN - Delay: 0
May 29 11:23:20 ccu3-webui user.debug xxxTest2: =============================================
May 29 11:23:10 ccu3-webui user.debug xxxTest: *xxxTest*   SONST  durch Systemvariable: XXLogik2 und dem Wert:ist falsch  um: 29.05. 11:23 Uhr
May 29 11:23:10 ccu3-webui user.debug xxxTest: SONST ausgeführt - false - false
May 29 11:23:10 ccu3-webui user.debug xxxTest2: Script-Aktion: SV A/B falsch - Sollergebnis-Prg: SONST - Delay: 0
May 29 11:23:10 ccu3-webui user.debug xxxTest2: =============================================

MichaelN0815 commented 3 years ago

Haben die Hinweise denn nun zu einer Spur geführt oder sollen wir noch was testen?

WP-0461 commented 3 years ago

Hm, …. so viel Energie in die Analyse gesteckt und nun keine Antwort, schade, aber den Grund werden wir dann sicherlich noch erfahren.