Skipte werden mehrfach ausgeführt?

[DavidT]

Hallo,

ich weiß nicht, ob es ein normales Verhalten ist, aber alle meine geschriebenen Skripte werden mehrfach ausgeführt:

` > 14:53:37.450 [info] javascript.0 Stop script script.js.common.Nachtmodus.Status_Nachtmodus

14:53:37.450 [info] javascript.0 Stop script script.js.common.Nachtmodus.Status_Nachtmodus

14:53:37.450 [info] javascript.0 Stop script script.js.common.Nachtmodus.Status_Nachtmodus

14:53:37.504 [info] javascript.0 Start javascript script.js.common.Nachtmodus.Status_Nachtmodus

14:53:37.505 [info] javascript.0 Start javascript script.js.common.Nachtmodus.Status_Nachtmodus

14:53:37.505 [info] javascript.0 Start javascript script.js.common.Nachtmodus.Status_Nachtmodus

14:53:37.505 [info] javascript.0 script.js.common.Nachtmodus.Status_Nachtmodus: registered 0 subscriptions and 0 schedules

14:53:37.505 [info] javascript.0 script.js.common.Nachtmodus.Status_Nachtmodus: registered 0 subscriptions and 0 schedules

14:53:37.505 [info] javascript.0 script.js.common.Nachtmodus.Status_Nachtmodus: registered 0 subscriptions and 0 schedules `

Ist das normal?

Gruß David

[Meistertr]

Das ist mir auch schon aufgefallen. Aufgefallen ist es mir nach dem Controller Update auf 1.2. Und dem Update des Javascript Adapters. Nach dem Start laufen Sie 3 mal durch aber im Betrieb fällt es mit nur auf wenn ich die trigger auf any stehen habe. Müsste sich @bluefox vielleicht mal anschauen.

Gesendet von meinem Handy

[andyb]

und ich hab schon an mir gezweifelt….bei mir auch

[andyb]

Haben nur wir 3 das Problem?

Anbei noch Auszug meiner Log

! javascript.0 2017-11-02 20:01:01.104 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:01.097 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:01.093 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:00.421 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:00.419 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:00.417 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:00.399 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:00.396 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:01:00.392 info script.js.aktiv.Ereignisliste: neuer Event zum verarbeiten: Brunnen ein
! javascript.0 2017-11-02 20:00:00.763 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 20:00:00.663 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 20:00:00.625 info script.js.aktiv.Servicemeldungen: Anzahl Homematic-Servicemeldungen: 0
! javascript.0 2017-11-02 20:00:00.623 info script.js.aktiv.Servicemeldungen: Homematic-Servicemeldungen:
! javascript.0 2017-11-02 20:00:00.605 info script.js.aktiv.Servicemeldungen: Anzahl Homematic-Servicemeldungen: 0
! javascript.0 2017-11-02 20:00:00.604 info script.js.aktiv.Servicemeldungen: Homematic-Servicemeldungen:
! javascript.0 2017-11-02 20:00:00.551 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 20:00:00.527 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 20:00:00.519 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 20:00:00.493 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 20:00:00.193 info script.js.aktiv.Servicemeldungen: Anzahl Homematic-Servicemeldungen: 0
! javascript.0 2017-11-02 20:00:00.192 info script.js.aktiv.Servicemeldungen: Homematic-Servicemeldungen:
! javascript.0 2017-11-02 19:55:00.754 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:55:00.728 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:55:00.721 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:55:00.625 info script.js.aktiv.Servicemeldungen: Anzahl Homematic-Servicemeldungen: 0
! javascript.0 2017-11-02 19:55:00.623 info script.js.aktiv.Servicemeldungen: Homematic-Servicemeldungen:
! javascript.0 2017-11-02 19:55:00.587 info script.js.aktiv.Servicemeldungen: Anzahl Homematic-Servicemeldungen: 0
! javascript.0 2017-11-02 19:55:00.586 info script.js.aktiv.Servicemeldungen: Homematic-Servicemeldungen:
! javascript.0 2017-11-02 19:55:00.242 info script.js.aktiv.Servicemeldungen: Anzahl Homematic-Servicemeldungen: 0
! javascript.0 2017-11-02 19:55:00.241 info script.js.aktiv.Servicemeldungen: Homematic-Servicemeldungen:
! javascript.0 2017-11-02 19:54:00.794 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:54:00.786 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:54:00.778 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:45:00.615 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:45:00.481 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:45:00.461 info script.js.aktiv.Verkehr.StauinArbeit: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:44:00.656 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:44:00.627 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10
! javascript.0 2017-11-02 19:44:00.549 info script.js.aktiv.Verkehr.StauinArbeit2: Anzahl Wegepunkte: 10

Edit:

Ich hab heute Cloud, Vis und socketio upgedatet. Latest

[andreasph]

Das Problem ist zwar schon etwas älter, aber ich habe das mit den aktuellen Admin- (3.4.7) und Scrip Engine- (3.6.4) Adaptern auch. Im Logfile sehe ich dass meine Skripte jeweils vier mal gestartet werden, alle mit dem gleichen Zeitstempel.

Gibt es hier neue Erkenntnisse?

[Thisoft]

JA, kann ich bestätigen. Das ist bei mir auch so. Allerdings hatte ich bisher eher den Eindruck dass die Scripte nicht wirklich mehrfach ausgeführt werden sondern dass das eher ein nicht ganz plausibles Logging ist…

Ich glaube da müsste wirklich jemand von den Entwicklern was dazu sagen. Bin gerne bereit dazu was zu testen etc.

[MarkusP]

Bei mir laufen die Scripte auch mehrfach, allerdings in einem zeitlichen Abstand von 2 Sekunden. Das führt bei mir z.B. dazu das meine Jalousien beim Ansteuern durch ein Skript verrückt spielen und die Lamellen mehrfach auf und zu gehen.

Weiterer negativer Nebeneffekt ist, dass der Dutycycle der CCU unnötig in die Höhe getrieben wird wenn Rolläden und Jalousien Abends schließen bzw. Morgens öffnen, da die Steuerbefehle tatsächlich mehrfach gesendet werden.

Wundere mich ein wenig, dass das Problem schon so lange besteht und es noch immer keine Lösung zu geben scheint. Das macht für mich die Script-Engine geradezu unbrauchbar.

[Homoran]

@MarkusP sagte in Skipte werden mehrfach ausgeführt?:

Wundere mich ein wenig, dass das Problem schon so lange besteht

"Das Problem" existiert aber nicht generell.
Wie soll irgendjemand das fixen, der dieses "Problem" nicht reproduzieren kann?

Dann nutzt es auch nicht in mehreren Threads zu posten

[AlCalzone]

Das Mehrfach-Loggen sieht man häufiger bei Leuten, die ihre Skripte über den scriptEnabled-Datenpunkt starten. Macht ihr das möglicherweise auch?

[MarkusP]

Bei mir werden keine Skripte über "scriptEnabled" gestartet.
Ich habe z.B. ein einfaches Skript, welches bei Golden-Hour die Lamellen meiner Jalousie ein Stück schließt.
Dieses Skript starte ich nach dem Editieren einmal. Am ersten Abend läuft es normal, am nächsten Tag doppelt, am übernächsten dreimal. Das merke ich dann daran, dass meine Jalousie anfängt zu spinnen (ständig auf-zu-auf-zu-auf-zu, abhängig davon wie oft das Skript läuft).

Hier noch der zugehörige Logauszug von gerade eben:

[AlCalzone]

@MarkusP sagte in Skipte werden mehrfach ausgeführt?:

Am ersten Abend läuft es normal, am nächsten Tag doppelt, am übernächsten dreimal.

Startest du täglich (automatisiert) den Adapter neu? Eventuell werden da die Schedules nicht sauber aufgeräumt.

[MarkusP]

@AlCalzone
Ja, ich starte täglich manuell neu, da mir sonst zu viel durcheinander gerät. Habe auch schon den kompletten ioBroker-Host neu gestartet, was aber am Verhalten nichts ändert.

Starte ich kurze Zeit vor Ausführung des obigen Skrips neu, läuft es richtig. Starte ich mehrere Stunden vorher neu, läuft es gleich beim ersten mal doppelt.

Es sieht so aus als würden die Skripte 1x gestartet und nach rund 15 Stunden dann ein zweites Mal.

[Wildbill]

@MarkusP sagte in Skipte werden mehrfach ausgeführt?:

@AlCalzone
Ja, ich starte täglich manuell neu, da mir sonst zu viel durcheinander gerät.

Ich denke, da solltest Du ansetzen um ohne automatisierte Neustarts auszukommen. Wenn alles sauber konfiguriert ist, läuft ioBroker (bei mir und anderen) über Monate ohne das kleinste Zucken.

Was genau gerät alles durcheinander?

Gruss, Jürgen

[MarkusP]

@Wildbill
Das "zuviel durcheinander" habe ich auf die Skripte bezogen. Ich meine damit, dass mir vor allem die Jalousien zu sehr spinnen und der DutyCycle der CCU in die Höhe schnellt wenn die Skripte die Jalousien/Rolläden zigmal ansteuern.

Ansonsten läuft ioBroker bei mir auch relativ problemlos und stabil. Die Skripte sind eben bei mir das große Problem.

[Wildbill]

Da sehe ich es aber wie @Homoran :

"Das Problem" existiert aber nicht generell.

Ein Problem, dass nur bei einigen wenigen auftritt nachzuverfolgen oder gar zu lösen ist schon schwer bis nahezu unmöglich. Vielleicht sollten, die, die das Problem haben, hier einfach mal zusätzliche Daten liefern, vielleicht findet man ja eine gemeinsame Auffälligkeit:

• Verwendete Hardware
• Verwendetes Betriebssystem
• Eingestelltes Repo im iobroker
• Verwendete Versionen (Admin, Javascript, ...)
• Multihost ja/nein
• iobroker-Host mit LAN oder WLAN im Netz
• Laufen alle Skripte mehrfach oder nur bestimmte (zum Beispiel nur die, die per Cron gestartet werden oder nur mit bestimmten Triggern)
• und und und

Gruss, Jürgen

[AlCalzone]

@MarkusP sagte in Skipte werden mehrfach ausgeführt?:

Das "zuviel durcheinander" habe ich auf die Skripte bezogen. Ich meine damit, dass mir vor allem die Jalousien zu sehr spinnen und der DutyCycle der CCU in die Höhe schnellt wenn die Skripte die Jalousien/Rolläden zigmal ansteuern.

Für mich scheint es aktuell aber eher so (auch wenn es nicht sein sollte), dass die Neustarts dein Problem erst hervorrufen.

[MarkusP]

@Wildbill

Hier mal die Daten zu meinem System:

Host ist ein MacMini Late 2013 mit osX High Sierra
RAM: 16 GB
Node.js: v8.11.3
NPM: 4.6.1
Admin: 3.6.0
JS-Engine: 4.1.12 (Problem bestand aber schon mit älteren Versionen)
Multihost nein
Host ist mit LAN verbunden
Repo: 1 default, 2 latest

Es laufen alle Skripte mit Triggern mehfach (auch Skripte, welche auf Werteänderungen triggern z.B. true nach false und umgekehrt).

[MarkusP]

@AlCalzone sagte in Skipte werden mehrfach ausgeführt?:

Für mich scheint es aktuell aber eher so (auch wenn es nicht sein sollte), dass die Neustarts dein Problem erst hervorrufen.

Weshalb scheint es für dich so, dass die Neustarts das Problem hervorrufen?
Nach einem Neustart läuft ja alles erstmal normal wie es soll, es sei denn der Neustart liegt zu lange zurück.

Beispiel: Golden Hour beginnt heute um 18:05 Uhr. Neustart habe ich gestern Abend gemacht. Das Skript wird also gleich doppelt laufen.
Hätte ich den Neustart sagen wir mal heute gegen 14 Uhr gemacht, dann würde es nur einmal laufen. Bin, wie schon erwähnt, auf rund 15 Stunden gekommen, ab dem ein Skipt beginnt sich zu verdoppeln.

[MarkusP]

Jetzt ist mir was merkwürdiges im Log aufgefallen:

undefined2019-03-26 18:05:02.815 - info: javascript.0 script.js.Jalousiesteuerung_Abend.JalousiesteuerungGoldenHour: Jalousie bei Golden Hour
2019-03-26 18:05:04.924 - info: javascript.0 script.js.Jalousiesteuerung_Abend.JalousiesteuerungGoldenHour: Jalousie bei Golden Hour

Was hat "undefined" zu bedeuten?

[Wildbill]

Das könnte genau das sein, was wir meinen, wenn wir schreiben, daß die Neustarts evtl. das Problem mit verursachen. Ich hatte solche Meldungen nach dem Update des Javascript Adapter weil alle Cron-Jobs, so wie Astro auch, nicht gelöscht wurden. Da half mir ein kompletter Reboot.
Und genau das könnte bei Dir passieren. Das durch iobroker Neustart eben was im System bleibt.
Wenn Du in die komplett einen Reboot machst und die iobroker Neustart stoppst, wie sieht es dann aus?

Gruß, Jürgen