Astro events triggers at wrong time after shutdown/restart

Hi All,

I am setting up my OH3, starting fresh, trying to do everything (or almost everything) thru UI. I am encountering an issue with Astro sun.

When I first setup the Thing, the events are triggering correctly. As it shows here:

2021-03-11 18:09:00.000 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:daylight#event triggered END
2021-03-11 18:12:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:civilDusk#event triggered START
2021-03-11 18:44:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:nauticDusk#event triggered START
2021-03-11 18:44:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:civilDusk#event triggered END
2021-03-11 19:21:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:astroDusk#event triggered START
2021-03-11 19:21:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:nauticDusk#event triggered END
2021-03-11 19:59:00.000 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:eveningNight#event triggered START
2021-03-11 19:59:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:astroDusk#event triggered END
2021-03-11 19:59:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:night#event triggered START
2021-03-12 00:00:30.718 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:morningNight#event triggered STAR

Then it turn off the computer for the night, as it’s a dev box, not meant to run 24/7. I turned on the computer around noon, on the day after. When I check the event log later the same day, here is what I found:

2021-03-11 18:09:00.000 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:daylight#event triggered END
2021-03-11 18:12:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:civilDusk#event triggered START
2021-03-11 18:44:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:nauticDusk#event triggered START
2021-03-11 18:44:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:civilDusk#event triggered END
2021-03-11 19:21:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:astroDusk#event triggered START
2021-03-11 19:21:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:nauticDusk#event triggered END
2021-03-11 19:59:00.000 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:eveningNight#event triggered START
2021-03-11 19:59:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:astroDusk#event triggered END
2021-03-11 19:59:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:night#event triggered START
2021-03-12 00:00:30.718 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:morningNight#event triggered START
2021-03-12 17:13:03.829 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:morningNight#event triggered END
2021-03-12 17:13:03.830 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:astroDawn#event triggered START
2021-03-12 17:50:03.829 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:astroDawn#event triggered END
2021-03-12 17:50:03.830 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:nauticDawn#event triggered START
2021-03-12 18:27:03.830 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:nauticDawn#event triggered END
2021-03-12 18:27:03.830 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:civilDawn#event triggered START
2021-03-12 18:59:03.829 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:rise#event triggered START
2021-03-12 18:59:03.830 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:51eadd7bde:civilDawn#event triggered END

MorningNight ended at 5ish PM and then down at 6ish PM?

Is there an event queue for Astro that it can only “pop” one event after another? I thought which event to trigger is based on time, not position of the queue?

If there is a queue, when does it get reset?

Thanks,
Joe

Astro generally calculates stuff for the day ahead just after midnight. Changes you make may not be effective until next day.
The above statement was in the forum.
Maybe because you turn it off it doesn’t calculate properly? Just a suggestion.

Quite possibly related but maybe not a direct fix for this - install MapDB as the secondary persistence layer. RRD (the default persistence) doesn’t handle strings, whereas (IIRC) MapDB and most others like InfluxDB/MySQL/etc can. Whatever you do, I’d recommend keeping RRD as the default though, from my experience, as it works incredibly well with OH3 requiring no additional config.

Yes, it also schedules the jobs at the same time as well. As it states here in the Thing handler code:

  /**
     * Schedules a positional and a daily job at midnight for Astro calculation and starts it immediately too. Removes
     * already scheduled jobs first.
     */

However the thing I am not sure is after it schedule the jobs, will it re-align the events. So sunset doesn’t get trigger at 12AM. I will leave the computer on and monitor the event after midnight, that should tell me if the issue would resolve itself.

Interesting, I will look into that.

Thanks,
Joe

To aid understanding, can you clarify if you got the expected dusk events after the unexpected dawn events shown?

It does look like a behind the scenes state machine. But I feel it isn’t.

In your openhab.log for boot time, you should see evidence of Astro setting itself up for the (rest of the) day ahead. Usually a couple of scheduled jobs. Confident the system time was accurate at that point?

There shouldn’t be any re-aligning to happen.
Example, reboot at 13:00.
Astro calculates today’s dawn for 09:00
We hope the code is smart enough not to schedule any event, as the time is already past.
Next dawn not calculated until midnight.

If you look at the state channel holding dawn DateTime, it always points to today’s calendar date, not tomorrows or next dawn.

Weird stuff happens at high latitudes, where there may not be a dawn at all today. So I suppose you should also check Astro is picking up correct lat/long at boot time.

Hi all,

Thank you all for all the info. I think I know why. After @rossko57 suggested to check the log during boot up, as the Astro should calculate events during boot, I realized openhab wasn’t rebooted after the computer rebooted.

The reason is openhab is in a VM. When I shut the host down, the VM went into suspended state instead of shut down. So when I rebooted the host, the VM just resume state.

As shown here:

2021-03-13 15:27:52.768 [DEBUG] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2021-03-13 15:27:52.792 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/START in 8947230ms (at 2021-03-13T17:57:00)
2021-03-13 15:27:52.793 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/END in 9187207ms (at 2021-03-13T18:01:00)
2021-03-13 15:27:52.794 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/night#event/START in 16447206ms (at 2021-03-13T20:02:00)
2021-03-13 15:27:52.796 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/START in 14167204ms (at 2021-03-13T19:24:00)
2021-03-13 15:27:52.798 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/END in 16447202ms (at 2021-03-13T20:02:00)
2021-03-13 15:27:52.800 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/START in 11947200ms (at 2021-03-13T18:47:00)
2021-03-13 15:27:52.800 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/END in 14167200ms (at 2021-03-13T19:24:00)
2021-03-13 15:27:52.800 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/START in 10087200ms (at 2021-03-13T18:16:00)
2021-03-13 15:27:52.801 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/END in 11947199ms (at 2021-03-13T18:47:00)
2021-03-13 15:27:52.802 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/eveningNight#event/START in 16447198ms (at 2021-03-13T20:02:00)
2021-03-13 15:27:52.803 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/daylight#event/END in 9847197ms (at 2021-03-13T18:12:00)
2021-03-13 15:27:52.812 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/SUN_SET in 9847189ms (at 2021-03-13T18:12:00)
2021-03-13 15:27:52.812 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NIGHT in 16447188ms (at 2021-03-13T20:02:00)
2021-03-13 15:27:52.813 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/ASTRO_DUSK in 14167187ms (at 2021-03-13T19:24:00)
2021-03-13 15:27:52.813 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NAUTIC_DUSK in 11947187ms (at 2021-03-13T18:47:0

Astro calculate events based on current time + ms. So when VM come out of suspend, the calculated seconds will be out of sync with the actual time, hence the events firing at incorrect time.

It’s all good now. I will shutdown the VM before shutdown the host, so that will ensure Astro calculate at boot.

Thanks all!

Joe

1 Like

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.