logic wird 2x getriggert (mit sunset)

[GHild]

Hallo,

ich habe eine einfache Logik, um 40 Minuten nach Sonnenuntergang die Rollläden zu schließen.

Hier der Aufruf der Logik:

Rollladen_Runter:
    filename: Rollladen_Runter.py
    crontab: 17:00<sunset+40m # at 40m after sunset but not before 17:00

Merkwürdigerweise wird diese Logik an manchen Tagen 2x im Abstand von 1 Sekunde getriggert:

Hier der Auszug aus den Log-Files:

smarthome-details.log.2022-03-24:2022-03-24 19:24:34 INFO logics.Rollladen_Runter GEH Rollladen Runter
smarthome-details.log.2022-03-24:2022-03-24 19:24:35 INFO logics.Rollladen_Runter GEH Rollladen Runter
smarthome-details.log.2022-03-25:2022-03-25 19:26:10 INFO logics.Rollladen_Runter GEH Rollladen Runter
smarthome-details.log.2022-03-26:2022-03-26 19:27:46 INFO logics.Rollladen_Runter GEH Rollladen Runter
smarthome-details.log.2022-03-27:2022-03-27 20:29:23 INFO logics.Rollladen_Runter GEH Rollladen Runter
smarthome-details.log.2022-03-28:2022-03-28 20:30:59 INFO logics.Rollladen_Runter GEH Rollladen Runter
smarthome-details.log.2022-03-29:2022-03-29 20:32:35 INFO logics.Rollladen_Runter GEH Rollladen Runter
smarthome-details.log.2022-03-29:2022-03-29 20:32:36 INFO logics.Rollladen_Runter GEH Rollladen Runter

Leider führt der 2. Aufruf (siehe 24.3. und 29.3.) dazu, dass die Rollläden stoppen und daher nicht schließen.

Ich nutze eine recht aktuelle Version:
SmartHomeNG v1.9.1-master (8133e714)
und kann mich nicht erinnern, dieses Problem in der Vergangenheit schon einmal beobachtet zu haben (nutze shng schon seit vielen Jahren), könnte also an der neuen Version liegen. Vielleicht an der Berechnung von sunset?

Irgendwelche Ideen? Wie kann ich weiter debuggen?

Danke,
Gerd

[bmx]

Moin Gerd!

Die Berechnung der crontab und sunset habe ich im letzten Jahr komplett neu aufgestellt. Dabei sind bei den crontabs Sekunden dazugekommen und ich habe einige Rundungen aufgelöst. Vielleicht hängt es damit zusammen.

Im Master ist auf jeden Fall die gleiche Version wie aktuell im develop. Spasseshalber könntest Du Dein Logging für diesen Fall mal um Mikrosekunden aufbohren und mit als PN Deinen Standort schicken, damit ich mir damit mal einen Testcase nachstellen kann.
Sowas ist leider nur recht schwer zu debuggen.

Ich habe mir gerade eine ähnliche Logik wie folgt gesetzt:

#!/usr/bin/env python3
# test_sunset.py

by = trigger.get('by', '')
source = trigger.get('source', '')
source_details = trigger.get('source_details','')
dest = trigger.get('dest', '')
value = trigger.get('value', '')
logger.warning(f'test_sunset getriggert (trigger[by={by}, source={source}, source_details={source_details}, dest={dest}, value={value}])')

mit einem crontab

sunset+1m | sunset+2m | sunset+3m | sunset+4m | sunset+5m | sunset+6m | sunset+7m | sunset+8m | sunset+9m | sunset+10m | sunset+11m | sunset+12m | sunset+13m | sunset+14m | sunset+15m | sunset+16m | sunset+17m | sunset+18m | sunset+19m | sunset+20m | sunset+21m | sunset+22m | sunset+23m | sunset+24m | sunset+25m | sunset+26m | sunset+27m | sunset+28m | sunset+29m | sunset+30m | sunset+31m | sunset+32m | sunset+33m | sunset+34m | sunset+35m | sunset+36m | sunset+37m | sunset+38m | sunset+39m | sunset+40m | sunset+41m | sunset+42m | sunset+43m | sunset+44m | sunset+45m | sunset+46m | sunset+47m | sunset+48m | sunset+49m | sunset+50m | sunset+51m | sunset+52m | sunset+53m | sunset+54m | sunset+55m | sunset+56m | sunset+57m | sunset+58m | sunset+59m | sunset+60m | sunset+61m | sunset+62m | sunset+63m | sunset+64m | sunset+65m | sunset+66m | sunset+67m | sunset+68m | sunset+69m | sunset+70m | sunset+71m | sunset+72m | sunset+73m | sunset+74m | sunset+75m | sunset+76m | sunset+77m | sunset+78m | sunset+79m | sunset+80m | sunset+81m | sunset+82m | sunset+83m | sunset+84m | sunset+85m | sunset+86m | sunset+87m | sunset+88m | sunset+89m | sunset+90m | sunset+91m | sunset+92m | sunset+93m | sunset+94m | sunset+95m | sunset+96m | sunset+97m | sunset+98m | sunset+99m | sunset+100m | sunset+101m | sunset+102m | sunset+103m | sunset+104m | sunset+105m | sunset+106m | sunset+107m | sunset+108m | sunset+109m

Bisher habe ich keine doppelten Einträge. Aber ich habe einen anderen Bug gefunden der seit Anfang drin zu sein scheint.

Interessehalber: Was für Hardware setzt Du ein?

[GHild]

Danke für die Unterstützung.

Heute ist das Problem wieder aufgetreten.
Hier das Log-File mit Millisekunden:

2022-03-31 20:35:47.219 INFO logics.Rollladen_Runter GEH Rollladen Runter
2022-03-31 20:35:48.230 INFO logics.Rollladen_Runter GEH Rollladen Runter

Standort kommt gleich als PN.

Grüße
Gerd

[GHild]

Als Hardware für smarthomeng nutze ich einen Beaglebone Black mit dem Cape von Robert.

Die Software ist ständig aktualisiert und auf einem recht neuen Stand.

> cat /etc/debian_version
10.11
> uname -a
Linux bbb 4.19.94-ti-r41 #1buster SMP PREEMPT Sat Mar 21 03:13:40 UTC 2020 armv7l GNU/Linux

In meiner Logik habe ich nur Schaltbefehle, die dann auf den KNX Bus gehen,
hier die ersten Zeilen:

logger.info("GEH Rollladen Runter")

### EG ###
sh.EG.GaesteWC.Rollladen.fahren(True)
sh.EG.HWR.Rollladen.fahren(True)
sh.EG.Wohnzimmer.Rollladen_Sued.pos(100)
...

Die Logik von dir kann ich morgen laufen lassen.

Grüße
Gerd

[bmx]

Ich habe das ganze für sunrise auch mal implementiert und kann es unabhängig von Deinem Wohnort nachvollziehen das die Logik mehrfach getriggert wird.

[bmx]

In meinen Setups habe ich folgenden Fix bereits getestet:

Im develop oder master branch in der Datei lib/scheduler.py Zeile 574 ein Kommentarzeichen vor die Zeile

now = now.replace(microsecond=0)

setzen. Dann sollten die doppelten Logiktrigger weg sein.

Wichtig:
Wer danach in seinem Log einen CRITICAL Error mit Scheduler Deadlock hat bitte unbedingt melden!

[bmx]

Nachdem bei mir kein Deadlock aufgetreten ist und auch sonst keine Nebenwirkungen evident wurden habe ich das in develop gepusht.

[GHild]

Nach etwas längerer Beobachtung meines Systems möchte ich auch noch die Rückmeldung geben, dass mit den vorgeschlagenen Anpassungen das Problem nicht mehr aufgetreten ist. Die Rollläden fahren zuverlässig 40 Minuten nach Sonnenuntergang runter 🌙

Vielen Dank, bmx
Gerd