Bug in 1.2.0: @time_active range without date (eg, sunrise, sunset or time) fails all days after HASS started

[markwhibbard]

Before upgrading to latest release, the following worked as intended. @time_active would cause it to only trigger during the daytime, not at night. However, after the upgrade, the behavior seems to be inverted. Restarting HASS results in correct behavior until the next day.

offset = 20

SCENES = [
    "switch.primary_lights",
    "switch.bedroom_lights",
    "switch.lower_level_lights",
]

@state_trigger(SCENES)
@time_active("range(sunrise + " + str(offset) + "m, sunset - " + str(offset) + "m)")
def auto_brighten(var_name=None, value=None):
    if value=="on":
        base_name = var_name.split('lights')[0]
        switch.turn_on(entity_id=base_name + "bright")

[craigbarratt]

There weren't any unit tests for @time_active using sunrise and sunset ranges, so I just added some. They do pass ok.

Since those don't show a problem, I'm going to run a live test, but I'll have to wait until tomorrow to see the results.

[craigbarratt]

I added this test to see what happens tomorrow. Can you run it too?

@time_trigger("period(midnight, 15m)")
@time_active("range(sunrise + 20m, sunset - 20m)")
def daylight():
    log.info("got a trigger between sunrise + 20m and sunset - 20m")

This should log a message every 15m between sunrise + 20m and sunset - 20m

[markwhibbard]

Done. Will do. Thanks!

[markwhibbard]

The bug manifests in the test script as well:

• Loaded test code last night. No log messages, as expected, during the night
• Once daylight, still no log messages.
• Reloaded pyscript scripts, still no log messages
• Restarted HASS, now getting log messages every 15 min

I believe my description above, about the behavior being "inverted" is not entirely correct. More accurately, it appears that the state returned by the @time_active(...) is stuck at whatever it evaluated to upon HASS startup. I will be able to further confirm this hypothesis at dusk tonight.

[craigbarratt]

Thanks for the update. My test worked correctly - no log messages overnight, and then they started this morning after sunrise.

With your observations, I looked at the code again. I can see how now might not be updated every loop in the trigger logic. I've committed a fix. Can you try the latest master version overnight?

[patrickfnielsen]

I have noticed the same behavior as @markwhibbard.
I have updated to the master version, and will let you know how the test goes.

[wsw70]

I can see how now might not be updated every loop in the trigger logic

@craigbarratt wasn't now supposed to assessed only once, at startup time, and mean "now, when the script starts"?

[craigbarratt]

Sorry about the confusion - I was referring to the internal notion of the current time in the trigger logic (the python variable is called now, and its date is used to augment time expressions that don't have dates like sunrise etc), not the user-level now that might appear in datetime expressions (which is unchanged and still has the meaning you stated).

[markwhibbard]

I pulled latest master and observed the behavior when we should have transitioned from daylight to not daylight, but I'm still seeing the same pathology, unfortunately.

I've looked over timer_active_check in trigger.py briefly to familiarize myself with what's going on there. There's a lot going on and I'm terrible with RegEx, so I don't follow it completely, but I will study that some more and put some debug logging in to see what's going on as I get some time in the coming days.

[markwhibbard]

When I insert the following:

    def timer_active_check(cls, time_spec, now, startup_time):
        """Check if the given time matches the time specification."""
        print(f"In timer active check with timespec: {time_spec} now {now} startup_time {startup_time}")

And I trigger my daylight check by turning on my _lights switch, now is always equal to startup time. So in trigger_watch, where this is called, I see:

                if trig_ok and self.time_active:
                    print(f"trig ok and time active now {now}")
                    if now is None:
                        now = dt_now()
                        print(f"Now is none so now {now}")
                        if startup_time is None:
                            startup_time = now
                    trig_ok = TrigTime.timer_active_check(self.time_active, now, startup_time)

[print statements inserted by me]
And upon startup, now gets set to dt_now b/c it is None, but after that, upon each trigger, now remains unchanged, b/c it is not None. I don't pretend to understand all the state logic here, but wouldn't you want to set now = dt_now every time you evaluate timer_active_check? When I get rid of the if now is None conditional, things seem to work ok.

Oops, hold on. Dumb mistake. It seems I didn't cp the latest master pull to the right place, so I'm not working off your fix. Your fix on line 930 would seem to fix this. I will actually get the latest code into the right place and monitor behavior tomorrow morning and report back. Sorry for the confusion.

[patrickfnielsen]

Just a FYI: Running on the latest version of master seems to have fixed the issue for me.

[markwhibbard]

Latest fix works for me too, once I figured out how to actually cp to the right place! Thanks @craigbarratt ! Been loving pyscript. Huge improvement to my hass experience.

[craigbarratt]

I released 1.2.1 with this fix, plus a few other minor ones. Thanks for finding and reporting this bug.