OH 2.4. Astro event stops firering

mrwee · April 1, 2019, 2:17pm

Running OH 2.4 on a Windows 10 pro (x64) machine with 4GB RAM. Java v8 update 191.

My problem is that the rule

rule “Sunrise”
when
Channel ‘astro:sun:local:rise#event’ triggered START
then
logInfo(“INFO”, “The sun came up”)
end

works one or two days (based on log entry), then it stop. A rule with

Channel ‘astro:sun:local:set#event’ triggered START

has the same problem, so it seems to be an Astro binding problem.
No other rule or functionality seems affected.

Astro binding:

202 | Active | 80 | 0.10.0.oh240 | Eclipse SmartHome Astro Binding

Any ideas why this happens?

rossko57 · April 1, 2019, 2:37pm

Would that be connected with daylight savings time? Someone else reported similar.

mrwee · April 1, 2019, 2:39pm

Unfortunately not. It failed before DST started yesterday.

mrwee · April 1, 2019, 3:02pm

Starting OH, gives me this in the logfiles:

2019-04-01 16:11:01.553 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘astro:sun:local’ to inbox.
2019-04-01 16:11:01.646 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘astro:moon:local’ to inbox.
2019-04-01 16:11:02.205 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2019-04-01 16:11:02.325 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local

so all good, besides the fact that it stops later on.

rlkoshak · April 1, 2019, 6:42pm

Watch the log file. You should see those “Scheduled Astro event” logs every day just after midnight. If you do not then it means that Astro is not scheduling the events. There was an error along these lines awhile back but I thought they got fixed.

mrwee · April 1, 2019, 7:31pm

I deleted the logfiles when restarting OH, will monitor the events and report back with the logfiles when it fails again (Actually had the same problem in 2.3, which was why I upgraded to 2.4)

mrwee · April 3, 2019, 6:35am

So, it failed again. No sun up event this morning. These are the logfiles:

openhab.log

2019-04-01 16:11:01.553 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'astro:sun:local' to inbox.
2019-04-01 16:11:01.646 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'astro:moon:local' to inbox.
2019-04-01 16:11:02.205 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2019-04-01 16:11:02.325 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local
2019-04-01 19:43:48.250 [INFO ] [.eclipse.smarthome.model.script.INFO] - The sun went down
2019-04-02 06:40:37.762 [INFO ] [.eclipse.smarthome.model.script.INFO] - The sun came up
2019-04-02 19:44:54.566 [INFO ] [.eclipse.smarthome.model.script.INFO] - The sun went down
2019-04-02 23:59:10.858 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2019-04-02 23:59:10.872 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local

events.log

2019-04-01 16:11:01.676 [.ItemChannelLinkAddedEvent] - Link 'Total_Radiation-astro:sun:home:radiation#total' has been added.
2019-04-01 16:11:01.695 [.ItemChannelLinkAddedEvent] - Link 'Sunset_Time-astro:sun:home:set#start' has been added.
2019-04-01 16:11:01.704 [.ItemChannelLinkAddedEvent] - Link 'MoonPhase-astro:moon:home:phase#name' has been added.
2019-04-01 16:11:01.707 [.ItemChannelLinkAddedEvent] - Link 'Diffuse_Radiation-astro:sun:home:radiation#diffuse' has been added.
2019-04-01 16:11:01.708 [.ItemChannelLinkAddedEvent] - Link 'Elevation-astro:sun:home:position#elevation' has been added.
2019-04-01 16:11:01.712 [.ItemChannelLinkAddedEvent] - Link 'Azimuth-astro:sun:home:position#azimuth' has been added.
2019-04-01 16:11:01.714 [.ItemChannelLinkAddedEvent] - Link 'Sunrise_Time-astro:sun:home:rise#start' has been added.
2019-04-01 16:11:01.753 [home.event.InboxAddedEvent] - Discovery Result with UID 'astro:sun:local' has been added.
2019-04-01 16:11:01.753 [home.event.InboxAddedEvent] - Discovery Result with UID 'astro:moon:local' has been added.
2019-04-01 16:11:02.246 [me.event.InboxRemovedEvent] - Discovery Result with UID 'astro:moon:local' has been removed.
2019-04-01 16:11:02.281 [hingStatusInfoChangedEvent] - 'astro:moon:local' changed from UNINITIALIZED to INITIALIZING
2019-04-01 16:11:02.337 [hingStatusInfoChangedEvent] - 'astro:moon:local' changed from INITIALIZING to ONLINE
2019-04-01 16:11:02.348 [me.event.InboxRemovedEvent] - Discovery Result with UID 'astro:sun:local' has been removed.
2019-04-01 16:11:02.367 [hingStatusInfoChangedEvent] - 'astro:sun:local' changed from UNINITIALIZED to INITIALIZING
2019-04-01 16:11:02.373 [hingStatusInfoChangedEvent] - 'astro:sun:local' changed from INITIALIZING to ONLINE
2019-04-01 19:43:48.248 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2019-04-01 19:43:48.253 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered END
2019-04-01 19:47:48.018 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered END
2019-04-01 19:47:48.019 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered START
2019-04-01 20:24:45.998 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered START
2019-04-01 20:24:45.999 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered END
2019-04-01 21:10:43.060 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered END
2019-04-01 21:10:43.061 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered START
2019-04-01 22:01:40.609 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered END
2019-04-01 22:01:40.611 [vent.ChannelTriggeredEvent] - astro:sun:local:night#event triggered START
2019-04-01 22:01:40.612 [vent.ChannelTriggeredEvent] - astro:sun:local:eveningNight#event triggered START
2019-04-02 00:00:04.431 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START
2019-04-02 04:25:45.180 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered END
2019-04-02 04:25:45.181 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered START
2019-04-02 05:16:42.382 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered END
2019-04-02 05:16:42.383 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered START
2019-04-02 06:02:39.938 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered END
2019-04-02 06:02:39.938 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered START
2019-04-02 06:22:38.801 [vent.ChannelTriggeredEvent] - astro:moon:local:rise#event triggered START
2019-04-02 06:40:37.759 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered END
2019-04-02 06:40:37.760 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered START
2019-04-02 06:44:37.569 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered END
2019-04-02 06:44:37.570 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered START
2019-04-02 13:14:16.072 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered START
2019-04-02 13:15:16.008 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered END
2019-04-02 16:20:05.794 [vent.ChannelTriggeredEvent] - astro:moon:local:set#event triggered END
2019-04-02 19:44:54.564 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered END
2019-04-02 19:44:54.564 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2019-04-02 19:48:54.102 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered START
2019-04-02 19:48:54.104 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered END
2019-04-02 20:25:52.348 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered START
2019-04-02 20:25:52.348 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered END
2019-04-02 21:12:49.725 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered END
2019-04-02 21:12:49.726 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered START
2019-04-02 22:03:46.939 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered END
2019-04-02 22:03:46.940 [vent.ChannelTriggeredEvent] - astro:sun:local:eveningNight#event triggered START
2019-04-02 22:03:46.940 [vent.ChannelTriggeredEvent] - astro:sun:local:night#event triggered START

rlkoshak · April 3, 2019, 3:35pm

It will help if How to use code fences instead of quotes.

2019-04-02 06:40:37.760 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered START

The events.log shows that Astro did work correctly. The trigger is there.

You don’t show openhab.log. Is the "The sun came up” log entry not there at 06:40:37?

Though I should note these logs are for yesterday. Do you have no logs for today?

rossko57 · April 3, 2019, 3:44pm

My reading is that astro did not do the expected recalculations around midnight, hence no new events.
There’s no evidence the job was scheduled at the preceeding midnight, but we’re only seeing excerpts.

Maybe boot time log will show astro job scheduling problem.

mrwee · April 3, 2019, 10:19pm

@rlkoshak The first log output is from openhab.log, there’s no “The sun came up”, which to me indicates that the rule didn’t run. There’s no entry today at all.

rlkoshak · April 3, 2019, 10:27pm

Well, it’s hard to tell because the log cuts off close to midnight on april 2. On april 2 there is both a log statement for the sun went down and came up.

And the events on the Things appear to have occurred for april 2.

Is there nothing at all in either logs for April 3rd?

As rossko57 said, you’ve filtered these logs so it’s hard to tell. All I can say from the logs is everything worked on april 2. I have nothing to tell me if it worked or not on april 3rd.

If there truly are no logs in either file on april 3rd then the problem is indeed Astro failed to reschedule the event.

rossko57 · April 4, 2019, 12:39am

Here are sample entries from boot openhab.log

2019-02-28 20:21:01.951 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:fosscross
2019-02-28 20:21:02.054 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:earlier

Here are sample entries for around midnight

2019-03-01 00:00:30.196 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:fosscross
2019-03-01 00:00:30.216 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:earlier

If we could see what was in your openhab.log it might be interesting.

mrwee · April 5, 2019, 6:13pm

I’ve move OH to another machine, so I’ll let it run until it fails again and update with logs

mrwee · April 9, 2019, 6:06pm

My openHAB has now been running on a virtual Windows 10 machine on an ESXi host for some days, without any astro problems. The previous installation was on a VirtualBox host. Maybe that’s the reason for the problems, I don’t know. All I know is that for now, it’s working. Thanks for your assistance!