Problems with sun_down sun_up

[HerrHofrat]

I noticed a strange issue with my light automation after upgrading from 3.0.5 to 4.0.2 - it should only trigger if the sun is down, but when the automation is triggered the first time every day, the sun_down function returns true - regardless the actual state of the sun or time of the day. I added some debug logs and this happened today:

2020-02-15 12:31:46.275683 INFO AutoLightHandlerCorridor: Next Sunrise: 2020-02-15 06:04:15+00:00 [self.AD.sched.next_sunrise())]
2020-02-15 12:31:46.280930 INFO AutoLightHandlerCorridor: Next Sunset: 2020-02-15 16:19:09+00:00 [self.AD.sched.next_sunset())]
2020-02-15 12:31:46.287261 INFO AutoLightHandlerCorridor: Sun down: True [self.AD.sched.sun_down())]
2020-02-15 12:31:46.293374 INFO AutoLightHandlerCorridor: Sun up: False [self.AD.sched.sun_up())]
2020-02-15 12:31:46.304108 INFO AutoLightHandlerCorridor: Sun down: True [self.sun_down())]
2020-02-15 12:31:46.311188 INFO AutoLightHandlerCorridor: Sun up: False [self.sun_up())]

The next sunrise is in the past and therefore the logic for sun_up/sun_down is messed up.

I'm using appdaemon in docker on a raspberry pi 3 B+ with Raspbian 10. Appdaemon is version 4.0.2 git commit 4bea956. I had to apk add libressl-dev in the Dockerfile to get it built successfully - no other changes were made. /etc/localtime is also mapped from the host to the container.

[ReneTode]

it would help if you share the code you use
edit: and there is no appdaemon 4.0.2 yet.
the latets release is 4.0.1
edit2: and please share your appdaemon.yaml and logs after you started AD.

[HerrHofrat]

Sure - appdaemon --version returns 4.0.2 in the docker container

"""Turn light on PIR trigger"""

import appdaemon.plugins.hass.hassapi as hass
import util
import datetime

TIME_DAY = datetime.time(6, 30, 0)
TIME_NIGHT = datetime.time(23, 0, 0)

class AutoLight(hass.Hass):
    """Scheduler for auto light."""
    
    def initialize(self):
        self.pir = util.get_arg(self.args, "pir")
        self.light = util.get_arg(self.args, "light")
        self.additional_trigger = util.get_arg(self.args, "trigger")
        self.delay = util.get_arg(self.args, "delay")
        self.nightmode = util.get_arg(self.args, "nightmode", False)
        self.should_log = util.get_arg(self.args, "should_log", False)
        self.handle = None

        self.listen_state(self._notify_state_change, self.pir)
        if self.additional_trigger is not None:
            self.listen_state(self._notify_state_change, self.additional_trigger)


    def _notify_state_change(self, entity, attribute, old, new, kwargs):
        #pylint: disable-msg=too-many-arguments
        del entity, attribute, old, kwargs #unused argument
        if new == "on":
            if self.handle != None:
                self.cancel_timer(self.handle)
            else:
                self._turn_on_light()
            self.handle = self.run_in(self._turn_off_light, self.delay)

    def _turn_on_light(self):
        now = datetime.datetime.now().time()
        brightness = 255
        if self.nightmode and (now < TIME_DAY or now > TIME_NIGHT):
            brightness = 5
        if self.sun_down():
            self.turn_on(self.light, brightness=brightness)
        self.create_task(self._log_sun_coroutine())

    def _turn_off_light(self, kwargs):
        del kwargs #unused argument
        if self.off_condition is not None and not self.off_condition():
            return
        if self.get_state(self.pir) == "on":
            self._notify_state_change(self.pir, None, "on", "on", None)
            return
        self.turn_off(self.light)
        self.handle = None
        
    async def _log_sun_coroutine(self):
        if self.should_log:
            self.log("--------------------------------------------------")
            self.log("Sun coroutine")
            self.log("--------------------------------------------------")
            self.log("Next Sunrise: %s", self.AD.sched.next_sunrise())
            self.log("Next Sunset: %s", self.AD.sched.next_sunset())
            self.log("Sun down: %s", await self.AD.sched.sun_down())
            self.log("Sun up: %s", await self.AD.sched.sun_up())
            self.log("Sun down: %s", await self.sun_down())
            self.log("Sun up: %s", await self.sun_up())
            self.log("--------------------------------------------------")

appdaemon:
  latitude: <redacted>
  longitude: <redacted>
  elevation: <redacted>
  time_zone: Europe/Vienna
  app_dir: /conf  
  plugins:
    HASS:
      type: hass
      ha_url: <redacted>
      token: <redacted>

2020-02-15 13:35:00.259203 INFO AppDaemon: AppDaemon Version 4.0.2 starting
2020-02-15 13:35:00.264032 INFO AppDaemon: Python version is 3.8.1
2020-02-15 13:35:00.264968 INFO AppDaemon: Configuration read from: /conf/appdaemon.yaml
2020-02-15 13:35:00.265712 INFO AppDaemon: Added log: AppDaemon
2020-02-15 13:35:00.266422 INFO AppDaemon: Added log: Error
2020-02-15 13:35:00.267246 INFO AppDaemon: Added log: Access
2020-02-15 13:35:00.267936 INFO AppDaemon: Added log: Diag
2020-02-15 13:35:00.376313 INFO AppDaemon: Loading Plugin HASS using class HassPlugin from module hassplugin
2020-02-15 13:35:00.478641 INFO HASS: HASS Plugin Initializing
2020-02-15 13:35:00.479609 INFO HASS: HASS Plugin initialization complete
2020-02-15 13:35:00.481294 INFO AppDaemon: HTTP is disabled
2020-02-15 13:35:00.515286 INFO HASS: Connected to Home Assistant 0.105.2
2020-02-15 13:35:00.598384 WARNING AppDaemon: App 'appdaemon' missing 'class' or 'module' entry - ignoring
2020-02-15 13:35:00.658786 INFO HASS: Evaluating startup conditions
2020-02-15 13:35:00.793808 INFO AppDaemon: Got initial state from namespace default
2020-02-15 13:35:01.100489 INFO AppDaemon: App <redacted> added (24 times)
2020-02-15 13:35:01.143063 INFO AppDaemon: Found 24 total apps
2020-02-15 13:35:01.144626 INFO AppDaemon: Starting Apps with 24 workers and 24 pins
2020-02-15 13:35:02.165396 INFO AppDaemon: Scheduler running in realtime
2020-02-15 13:35:02.177618 INFO AppDaemon: Adding /conf to module import path
2020-02-15 13:35:02.178897 INFO AppDaemon: Adding /conf/compiled to module import path
2020-02-15 13:35:02.180187 INFO AppDaemon: Adding /conf/compiled/css to module import path
2020-02-15 13:35:02.181324 INFO AppDaemon: Adding /conf/compiled/javascript to module import path
2020-02-15 13:35:02.182680 INFO AppDaemon: Adding /conf/apps to module import path
2020-02-15 13:35:02.184015 INFO AppDaemon: Adding /conf/apps/<redacted> to module import path
2020-02-15 13:35:02.203056 INFO AppDaemon: Adding /conf/dashboards to module import path
2020-02-15 13:35:02.204118 INFO AppDaemon: Adding /conf/namespaces to module import path
2020-02-15 13:35:02.275622 INFO AppDaemon: Loading Global Module: /conf/apps/util.py
2020-02-15 13:35:02.285993 INFO AppDaemon: Loading App Module: /conf/apps/<redacted>
2020-02-15 13:35:02.356433 INFO AppDaemon: Loading Global Module: /conf/apps/<redacted>
2020-02-15 13:35:02.400498 INFO AppDaemon: Loading App Module: /conf/apps/<redacted>

[ReneTode]

i think its a bad idea to mix sync apps with async functions.
a simple run_in would do the trick as well and that wouldnt make your app async.

and it seems that Andrew already did set dev to 4.0.2 so you are running a dev version.

i just tested

import appdaemon.plugins.hass.hassapi as hass

class AutoLight(hass.Hass):
    
    def initialize(self):
        self.log(self.sun_down())

and it returns false as expected.

so please try to use a sync way to log to see if that makes a difference.
and you could try the test app i used to see if there is something strange going on in your case.

and please dont use unsupported ways like:
self.AD.sched.next_sunset()

you can simply use
self.sunset() to see the next sunset.

[HerrHofrat]

I used the unsupported api just to point out that next_sunrise is in the past

2020-02-15 12:31:46.275683 INFO AutoLightHandlerCorridor: Next Sunrise: 2020-02-15 06:04:15+00:00 [self.AD.sched.next_sunrise())]
2020-02-15 12:31:46.280930 INFO AutoLightHandlerCorridor: Next Sunset: 2020-02-15 16:19:09+00:00 [self.AD.sched.next_sunset())]

at 12:31 the next sunrise returns 6:04 for the same day - this should not be possible?
and this happens only the first time each day when this automation is triggered. After that sun_up/down behaves normally, until the next day

I only mixed sync/async to await the async functions for logging purposes - it is the same when I also do that with just sync functions

[ReneTode]

I used the unsupported api just to point out that next_sunrise is in the past

it helps more if you use supported api to point out something is wrong ;)

at 12:31 the next sunrise returns 6:04 for the same day - this should not be possible?

that is correct. so now we need to find out why you get a wrong sunrise back the first time.
and that can be because something is saved somewhere, and you are calling an old setting.

I only mixed sync/async to await the async functions for logging purposes - it is the same when I also do that with just sync functions

i can see you did it for logging, still its better just not to do it.
async is added in AD to make async apps possible for situations where its needed, but still we advise only to use it if you cant avoid it, because it brings risks and possibly unsuspected situations.

i am trying to find out if its something in this app that makes that it gives back the wrong info or that its something in general.
and i just called self.sunset() and self.sunrise() for the first time this day (because i never use it) and it gives the right info.
so we need to figure out why its not giving the right info in your case.

so if you would try to add logging this way:

    def initialize(self):

        self.listen_state(self._log_now, self.pir)

    def _log_now(self, entity, attribute, old, new, kwargs):
        if self.should_log:
            self.log("--------------------------------------------------")
            self.log("Sun logging")
            self.log("--------------------------------------------------")
            self.log("Next Sunrise: %s", self.sunrise())
            self.log("Next Sunset: %s", self.sunset())
            self.log("Sun down: %s", self.sun_down())
            self.log("Sun up: %s", self.sun_up())
            self.log("--------------------------------------------------")

we can make sure that its not something else that is creating the problem.

[HerrHofrat]

I also have the impression that sun_down uses an old setting - that's why I tryed to not only log the official api, but also internal values to find discrepancies.

I'll adapt the logging accordingly - I also logged self.AD.sched.get_now()) for now and it turns out that this time is also not correct (-1h), although the time_zone(self.AD.time_zone) should be set correctly:

2020-02-15 14:44:22.416879 INFO AutoLightHandlerCorridor: Timezone: Europe/Vienna
2020-02-15 14:44:22.426116 INFO AutoLightHandlerCorridor: Now: 2020-02-15 13:44:22.418426+00:00

[ReneTode]

thats the problem with internal values.
they are supposed to be internal, and when they give back wrong values that isnt important, when the official api returns the right values.

i leave the internal coding to the other devs, but i can imagine that get_now() is used internally some other way and is corrected when the time is given to the user.

does your logging show the right time?
do the documented api's give the correct times?
do run_daily etc. run at the correct time?
if so then there is nothing to worry when internal settings are different.

[ReneTode]

i also advise to add the admin interface to your appdaemon.yaml
it will help you to make visible what callbacks will run at what time, how much they run, etc.
which is very helpfull for debugging purposes.

[ReneTode]

@HerrHofrat i didnt notice it at first, but i saw strange behaviour in your logs.

you got

  app_dir: /conf  

in your appdaemon.yaml
which is a very bad idea.
conf contains also your configuration files, and it will result in very strange stuff when you do this.
please change the line to:

  app_dir: /conf/apps  

to make sure AD will function correctly.
AD looks every loop run for changes in the dir you set there and tries to create apps from all yaml and py it finds in there.

[HerrHofrat]

thats the problem with internal values.
they are supposed to be internal, and when they give back wrong values that isnt important, when the official api returns the right values.

self.get_now() also returns a wrong time (-1h): the time of the log would be the correct one
2020-02-15 16:57:44.986764 INFO AutoLightHandlerCorridor: Time: 2020-02-15 15:57:44.970733+00:00
need to test run_daily - will get back to that later.

Thanks for pointing out the app_dir issue, fixed that!

i also advise to add the admin interface to your appdaemon.yaml
Thanks for that, was not aware that this exists 😂

I also changed the logging to only use the official API

Here are the logs from today - with the official API: the first time triggered at 8:49 Sun Down returned True, while the second trigger at 9:05 returned False

2020-02-16 08:49:21.491191 INFO AutoLightHandlerCorridor: Time: 2020-02-16 07:49:21.487512+00:00
2020-02-16 08:49:21.497494 INFO AutoLightHandlerCorridor: Next Sunrise: 2020-02-16 07:02:34
2020-02-16 08:49:21.504659 INFO AutoLightHandlerCorridor: Next Sunset: 2020-02-16 17:20:45
2020-02-16 08:49:21.510864 INFO AutoLightHandlerCorridor: Sun down: True
2020-02-16 08:49:21.517287 INFO AutoLightHandlerCorridor: Sun up: False

2020-02-16 09:05:02.581335 INFO AutoLightHandlerCorridor: Time: 2020-02-16 08:05:02.577845+00:00
2020-02-16 09:05:02.587911 INFO AutoLightHandlerCorridor: Next Sunrise: 2020-02-17 07:00:51
2020-02-16 09:05:02.594327 INFO AutoLightHandlerCorridor: Next Sunset: 2020-02-16 17:20:45
2020-02-16 09:05:02.600442 INFO AutoLightHandlerCorridor: Sun down: False
2020-02-16 09:05:02.606843 INFO AutoLightHandlerCorridor: Sun up: True

do run_daily etc. run at the correct time?
I can confirm that run_daily runs at the correct time

[ReneTode]

if self.get_now() returns the wrong time then somewhere a setting must be off.
i think that @acockburn can ask better questions related to that.

i dont use docker but venv, and for me all times are correct.

[HerrHofrat]

So, I think I found an issue - I again added some logging of internal values of the scheduler. self.AD.sched.now is not up to date, therefore the if in scheduler.py#L220 is true.

Probably in the if self.get_now() should be used?

2020-02-26 09:46:15.930492 INFO AutoLightHandlerCorridor: self.AD.sched.now: 2020-02-26 00:17:55.002202+00:00
2020-02-26 09:46:15.935078 INFO AutoLightHandlerCorridor: self.AD.sched.get_now_sync: 2020-02-26 08:46:15.931552+00:00
2020-02-26 09:46:15.944301 INFO AutoLightHandlerCorridor: next_rising_dt: 2020-02-26 05:44:36+00:00

2020-02-26 09:46:15.975179 INFO AutoLightHandlerCorridor: Time: 2020-02-26 08:46:15.970074+00:00
2020-02-26 09:46:15.982495 INFO AutoLightHandlerCorridor: Next Sunrise: 2020-02-26 06:44:36
2020-02-26 09:46:15.989728 INFO AutoLightHandlerCorridor: Next Sunset: 2020-02-26 17:36:33
2020-02-26 09:46:15.997108 INFO AutoLightHandlerCorridor: Sun down: True
2020-02-26 09:46:16.004890 INFO AutoLightHandlerCorridor: Sun up: False

[acockburn]

Correct - self.AD.sched.now is only updated infrequently, which was a change that went into 4.0 - the wrinkle here is that you are using a listen_state() to trigger the lookup. I had tested that any time related triggesr should update now appropriately but forgot about listen_states (). Your fix would work, but it would still be broken for time travel so I need to make the scheduler update every time now is accessed internally

[acockburn]

OK, I made a fix and pushed it to dev. It's kind of hard for me to test it, so I was hoping you could take a look. If you aren't comfortable using a dev build it will be in the next full build for you to take a look at (4.0.4). Please let me know if this fixes the issue.

[acockburn]

Scratch that - I had to recert the change it caused an issue ... watch this space

[thd6n75]

Here's another code snippet and logs that (I think) demonstrate this issue https://community.home-assistant.io/t/sunset-trigger-not-working/90764/8

[thd6n75]

For anyone else who's impact by this, there's an (alleged) workaround posted at the bottom of #926 (comment)

[thd6n75]

This problem still exists in the 4.0.4 docker image. Here's the workaround I implemented in the meantime: a cronjob runs docker restart appdaemon every day.

[acockburn]

Fixed some bugs in this area in the current dev (for 4.1.0) - please re-open if there is still an issue.