sun_up/down never changes its value

[mhoyer]

I was wondering why my door entrance automation sometimes has some hick-ups. The intent was to switch on the lights in the hall when someone opens the door. But if the sun is up, the lights should not switch. The problem I faced: sometimes it worked, sometimes not. The more I focused on this strange behavior the more I found that the sun_up function somehow flipped with some kind of delay from True to False and back. First I though it was due to some timezone thingy or so. But I digged deeper into the code and probably found the issue:

The AppDaemon API function sun_up() calls a function with the same name on the scheduler class which in turn invokes both next_sunrise() and next_sunset() functions to do the comparison if the sun should currently be up.

Looking at for instance next_sunrise() function one can see that it's using self.now property to calculate the next possible date time object for a sunrise. I found that self.now is sticky and not updating properly. In fact I was able to create a single application to reproduce the issue:

import appdaemon.plugins.hass.hassapi as hass

class DebugAutomation(hass.Hass):

  def initialize(self):
    self.listen_state(self.on_switch_triggered, "MY_HASS_SENSOR_SWITCH", attribute="state")
    # self.run_every(self.heartbeat, "now", 10)

  def on_switch_triggered(self, entity, attribute, old, new, kwargs):
    self.log(f"debugswitch: {self.sun_up()} {self.AD.sched.now}")

  def heartbeat(self, kwargs):
    self.log(f"heartbeat: {self.AD.sched.now}")

I also found a hackish workaround. Just uncomment the self.run_every line in the example above and the switch starts to work (at least in 10s update cycles). Why? I assume that the run_every() timer triggers the scheduler event loop regularly, which seems to update the self.now property accordingly.

The corresponding apps.yaml:

debug:
  module: debug
  class: DebugAutomation
  global_dependencies: global

I am now wondering if the implementations of next_sunset() and next_sunrise() in the scheduler should get the current time from a function instead of that static now property? Or is there anything I did wrong in my automation class?

Environment: appdaemon 4.2.1 running inside docker container on a raspberry pi 4.

[Justihar]

Not sure if I'm really replicating your issue but I ran a quick test using both sun_up and sun_down every 2 hours with timewarp and here are my results.

import adbase

class Test(adbase.ADBase):
    def initialize(self):
        self.adapi = self.get_ad_api()
        self.adapi.run_every(self.cb, self.adapi.get_now(), 7200)

    def cb(self, kwargs):
        self.adapi.log(f"current datetime: {self.adapi.get_now()}")
        self.adapi.log(
            f"is sun up?: {self.adapi.sun_up()}, is sun down?: {self.adapi.sun_down()}"
        )

2022-10-01 01:08:24.000000 DEBUG test: Registering run_every starting 2022-10-01 01:08:24-07:00 in 7200s intervals for test 2022-10-01 01:46:58.500000 INFO test: current datetime: 2022-10-01 01:46:58.500000-07:00 2022-10-01 01:46:58.500000 INFO test: is sun up?: False, is sun down?: True 2022-10-01 03:08:24.000000 INFO test: current datetime: 2022-10-01 03:08:24-07:00 2022-10-01 03:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-01 05:08:24.000000 INFO test: current datetime: 2022-10-01 05:08:24-07:00 2022-10-01 05:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-01 07:08:24.000000 INFO test: current datetime: 2022-10-01 07:08:24-07:00 2022-10-01 07:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-01 09:08:24.000000 INFO test: current datetime: 2022-10-01 09:08:24-07:00 2022-10-01 09:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-01 11:08:24.000000 INFO test: current datetime: 2022-10-01 11:08:24-07:00 2022-10-01 11:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-01 13:08:24.000000 INFO test: current datetime: 2022-10-01 13:08:24-07:00 2022-10-01 13:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-01 15:08:24.000000 INFO test: current datetime: 2022-10-01 15:08:24-07:00 2022-10-01 15:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-01 17:08:24.000000 INFO test: current datetime: 2022-10-01 17:08:24-07:00 2022-10-01 17:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-01 19:08:24.000000 INFO test: current datetime: 2022-10-01 19:08:24-07:00 2022-10-01 19:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-01 21:08:24.000000 INFO test: current datetime: 2022-10-01 21:08:24-07:00 2022-10-01 21:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-01 23:08:24.000000 INFO test: current datetime: 2022-10-01 23:08:24-07:00 2022-10-01 23:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-02 01:08:24.000000 INFO test: current datetime: 2022-10-02 01:08:24-07:00 2022-10-02 01:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-02 03:08:24.000000 INFO test: current datetime: 2022-10-02 03:08:24-07:00 2022-10-02 03:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-02 05:08:24.000000 INFO test: current datetime: 2022-10-02 05:08:24-07:00 2022-10-02 05:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-02 07:08:24.000000 INFO test: current datetime: 2022-10-02 07:08:24-07:00 2022-10-02 07:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-02 09:08:24.000000 INFO test: current datetime: 2022-10-02 09:08:24-07:00 2022-10-02 09:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-02 11:08:24.000000 INFO test: current datetime: 2022-10-02 11:08:24-07:00 2022-10-02 11:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-02 13:08:24.000000 INFO test: current datetime: 2022-10-02 13:08:24-07:00 2022-10-02 13:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-02 15:08:24.000000 INFO test: current datetime: 2022-10-02 15:08:24-07:00 2022-10-02 15:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-02 17:08:24.000000 INFO test: current datetime: 2022-10-02 17:08:24-07:00 2022-10-02 17:08:24.000000 INFO test: is sun up?: True, is sun down?: False 2022-10-02 19:08:24.000000 INFO test: current datetime: 2022-10-02 19:08:24-07:00 2022-10-02 19:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-02 21:08:24.000000 INFO test: current datetime: 2022-10-02 21:08:24-07:00 2022-10-02 21:08:24.000000 INFO test: is sun up?: False, is sun down?: True 2022-10-02 23:08:24.000000 INFO test: current datetime: 2022-10-02 23:08:24-07:00 2022-10-02 23:08:24.000000 INFO test: is sun up?: False, is sun down?: True

[mhoyer]

@Justihar, well, you're exactly using my "workaround" by having self.adapi.run_every(...) in your example. Hence, this "timer" will update the now property every time it fires before your action cb() function is executed. Thus, also the sun_up() and sun_down() calls will work as shown in your output. Also be aware, that I did not have any issue with calling get_now(). But the property inside the scheduler instance will not update if you do not stimulate that loop logic.

To re-phrase the problem: Try to not use any run_at(), run_in(), or run_every() (or any other run_*()) function to check on sun_up() or sun_down(). Use some "external" trigger, like I did with the listen_state() function.

And to complete my initial post here the output I saw with the code from OP:

2022-09-29 20:32:37.866369 INFO AppDaemon: Reloading Module: /conf/apps/debug.py
2022-09-29 20:32:37.872219 INFO AppDaemon: Initializing app debug using class DebugAutomation from module debug
2022-09-29 20:32:43.083534 INFO debug: debugswitch: False 2022-09-29 18:32:29.004059+00:00
2022-09-29 20:32:43.391343 INFO debug: debugswitch: False 2022-09-29 18:32:29.004059+00:00
2022-09-29 20:32:44.510731 INFO debug: debugswitch: False 2022-09-29 18:32:29.004059+00:00
2022-09-29 20:32:45.599105 INFO debug: debugswitch: False 2022-09-29 18:32:29.004059+00:00
2022-09-29 20:32:46.410782 INFO debug: debugswitch: False 2022-09-29 18:32:29.004059+00:00
2022-09-29 20:32:47.738551 INFO debug: debugswitch: False 2022-09-29 18:32:29.004059+00:00

[Justihar]

Yeah, that actually makes a lot of sense. I'll do some additional testing.

[Justihar]

Here is an update to my test. I used an input_boolean entity from HA and manually turned it on and off.

class Test(adbase.ADBase):
    def initialize(self):
        self.adapi = self.get_ad_api()
        self.test_entity = self.adapi.get_entity("input_boolean.test_bool_1")
        self.test_entity.listen_state(self.entity_cb)

    def entity_cb(self, entity, attribute, old, new, kwargs):
        self.adapi.log(
            f"state: {new}, is sun up?: {self.adapi.sun_up()}, is sun down?: {self.adapi.sun_down()}"
        )

2022-09-30 10:47:06.840000 INFO test: state: on, is sun up?: True, is sun down?: False
2022-09-30 18:21:01.580000 INFO test: state: off, is sun up?: True, is sun down?: False
2022-09-30 23:25:26.380000 INFO test: state: on, is sun up?: False, is sun down?: True
2022-10-01 05:23:40.830000 INFO test: state: off, is sun up?: False, is sun down?: True
2022-10-01 09:56:17.840000 INFO test: state: on, is sun up?: True, is sun down?: False
2022-10-01 14:41:31.000000 INFO test: state: off, is sun up?: True, is sun down?: False
2022-10-01 20:25:45.330000 INFO test: state: on, is sun up?: False, is sun down?: True
2022-10-02 01:59:16.050000 INFO test: state: off, is sun up?: False, is sun down?: True
2022-10-02 07:38:47.630000 INFO test: state: on, is sun up?: True, is sun down?: False
2022-10-02 11:15:46.210000 INFO test: state: off, is sun up?: True, is sun down?: False
2022-10-02 18:18:11.230000 INFO test: state: on, is sun up?: True, is sun down?: False
2022-10-03 00:12:33.040000 INFO test: state: off, is sun up?: False, is sun down?: True
2022-10-03 06:53:59.280000 INFO test: state: on, is sun up?: True, is sun down?: False
2022-10-03 12:23:09.680000 INFO test: state: off, is sun up?: True, is sun down?: False
2022-10-03 17:52:49.400000 INFO test: state: on, is sun up?: True, is sun down?: False
2022-10-04 01:55:44.230000 INFO test: state: off, is sun up?: False, is sun down?: True
2022-10-04 06:00:21.230000 INFO test: state: on, is sun up?: False, is sun down?: True
2022-10-04 14:11:42.860000 INFO test: state: off, is sun up?: True, is sun down?: False
2022-10-04 23:36:34.550000 INFO test: state: on, is sun up?: False, is sun down?: True
2022-10-05 03:45:40.730000 INFO test: state: off, is sun up?: False, is sun down?: True
2022-10-05 14:06:14.070000 INFO test: state: on, is sun up?: True, is sun down?: False
2022-10-05 20:54:59.100000 INFO test: state: off, is sun up?: False, is sun down?: True
2022-10-06 01:48:21.830000 INFO test: state: on, is sun up?: False, is sun down?: True

[mhoyer]

@Justihar, may I ask how you simulate the clock in your example? Obviously you're not waiting hours to trigger your input_boolean.test_bool_1 trigger over and over again?

I fear your time lapsing approach also updates that now property of the scheduler instance, which then makes the results of sun_down and sun_up work properly.

[mhoyer]

Ok. Some news. I tried to replay your most recent example. Though, I don't know how you managed to simulate that time lapse.

I extended your example slightly by adding that now property to the log output:

    def entity_cb(self, entity, attribute, old, new, kwargs):
        self.adapi.log(
-            f"state: {new}, is sun up?: {self.adapi.sun_up()}, is sun down?: {self.adapi.sun_down()}"
+            f">> {self.adapi.AD.sched.now} << state: {new}, is sun up?: {self.adapi.sun_up()}, is sun down?: {self.adapi.sun_down()}"
        )

I just found by accident that at least every 60 seconds the now property of the scheduler updates somehow "magically" in the background.

2022-10-01 13:21:18.294054 INFO AppDaemon: App initialization complete
2022-10-01 13:21:21.565574 INFO debug: >> 2022-10-01 11:21:19.281351+00:00 << state: off, is sun up?: True, is sun down?: False
2022-10-01 13:21:33.649573 INFO debug: >> 2022-10-01 11:21:19.281351+00:00 << state: on, is sun up?: True, is sun down?: False
2022-10-01 13:22:09.873176 INFO debug: >> 2022-10-01 11:21:19.281351+00:00 << state: off, is sun up?: True, is sun down?: False
2022-10-01 13:22:15.103123 INFO debug: >> 2022-10-01 11:21:19.281351+00:00 << state: on, is sun up?: True, is sun down?: False
... after 60s the now propery updates ...               ▽▽
2022-10-01 13:22:19.300947 INFO debug: >> 2022-10-01 11:22:19.284281+00:00 << state: off, is sun up?: True, is sun down?: False
2022-10-01 13:22:19.704890 INFO debug: >> 2022-10-01 11:22:19.284281+00:00 << state: on, is sun up?: True, is sun down?: False
2022-10-01 13:22:22.131180 INFO debug: >> 2022-10-01 11:22:19.284281+00:00 << state: off, is sun up?: True, is sun down?: False

I am going to dig deeper if I still have an issue with my code.

[mhoyer]

Further insights. I again debugged my larger application stack and still found that the now property is not updating. Finally I found why and am now able to also reproduce in your example: As soon as there is at least one scheduler callback registered, this magic 60s background update will not work anymore. Only when my own registered scheduler callbacks fire, the now prop will be updated.

import adbase

class DebugAutomation(adbase.ADBase):
    def initialize(self):
        self.adapi = self.get_ad_api()
        self.test_entity = self.adapi.get_entity("input_boolean.test_bool_1")
        self.test_entity.listen_state(self.entity_cb)
+       self.adapi.run_daily(self.noop_handler, "00:00:00")

+   def noop_handler(self, *args, **kwargs):
+       return

    def entity_cb(self, entity, attribute, old, new, kwargs):
        self.adapi.log(
            f">> {self.adapi.AD.sched.now} << state: {new}, is sun up?: {self.adapi.sun_up()}, is sun down?: {self.adapi.sun_down()}"
        )

You see in the example above I just added a run_daily scheduler callback to trigger every day at midnight a noop_handler.

[Justihar]

@Justihar, may I ask how you simulate the clock in your example? Obviously you're not waiting hours to trigger your input_boolean.test_bool_1 trigger over and over again?

I fear your time lapsing approach also updates that now property of the scheduler instance, which then makes the results of sun_down and sun_up work properly.

I used the timewarp option. https://appdaemon.readthedocs.io/en/latest/APPGUIDE.html?#speeding-things-up

[mhoyer]

Hi @Justihar. Sorry for late reply.

I now also tried to start appdaemon with -t option. Sadly, this really influences the behavior of the test setup and the reproduction of my issue is not doable with this feature enabled.

Again, my findings lead to the fact that the now property of the Scheduler class (https://github.com/AppDaemon/appdaemon/blob/4.2.1/appdaemon/scheduler.py#L30) will not receive any update with those conditions:

• you only have one or more "State Callbacks" and no other callbacks registered
• you start appdaemon without timewarp
• you do not jump around on the AppDaemon dashboard (e.g. check locally under http://localhost:5050/aui/index.html#/state?tab=callbacks)

And if the now property never ever changes while AppDaemon is running, there will also never be a change to the results of sun_up() and sun_down() functions.

I know, it's a pretty tough to reproduce as you really have to wait for a concrete sunset/sunrise on a day. But my setup at home simply fulfills those criteria above.

[acockburn]

This is probably an artifact of the new scheduler added several releases ago and no-one noticed! Marking as a bug for a fix when I am next in that area of the code.

[acockburn]

Just to clarify - the now not updating is expected behavior, it is an internal variable that is only updated when the scheduler actually does something which explains the above behavior which is expected. The problem here is that there is no registered scheduler event to change the sunrise state unless you force it, so I need to add one for sunrise and one for sunset.

[acockburn]

@mhoyer - I have a candidate fix in dev if you are able to test it - I'll test it too tonight and tomorrow morning.

[acockburn]

I spoke too soon, the fix caused some other issues so I reverted it. Will take another look soon.

[mhoyer]

Ok. Thanks for your efforts already. Let me know if I can support or test a version.

[acockburn]

OK, took another look - checking my new fix, should know more in a day or two!

[acockburn]

This is now fixed in dev and will be in the next release