Astro: events sometimes not fired

[usambara (Ulrich)]

I’m on OH 3.3, the described effect is with M1 and M2.

Sometimes certain events are missing. And when these are missing the related rules aren’t executed

In this example from today all evening events (set, civilDusk, nauticDusk, astroDusk, eveningNight, night) are missing (with M2).

openhabian@kopf:~ $ grep "astro:sun:dahoam:" /var/log/openhab/events.log
2022-03-05 00:27:04.705 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:morningNight#event triggered START
2022-03-05 05:48:53.330 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:morningNight#event triggered END
2022-03-05 05:48:53.332 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:astroDawn#event triggered START
2022-03-05 06:28:27.895 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:nauticDawn#event triggered START
2022-03-05 06:28:27.896 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:astroDawn#event triggered END
2022-03-05 07:06:47.575 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:nauticDawn#event triggered END
2022-03-05 07:06:47.577 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:civilDawn#event triggered START
2022-03-05 07:38:05.818 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:civilDawn#event triggered END
2022-03-05 07:38:05.820 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:rise#event triggered START
2022-03-05 07:40:19.074 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:rise#event triggered END
2022-03-05 07:40:19.076 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:daylight#event triggered START
2022-03-05 13:32:49.660 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:noon#event triggered START
2022-03-05 13:33:30.621 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:noon#event triggered END

In this example the noon events are missing (with M1).

openhabian@kopf:~ $ grep "astro:sun:dahoam:" /var/log/openhab/History/events.log.4
2022-03-01 00:00:51.552 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:morningNight#event triggered START
2022-03-01 05:17:28.316 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:astroDawn#event triggered START
2022-03-01 05:17:28.318 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:morningNight#event triggered END
2022-03-01 05:53:24.015 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:astroDawn#event triggered END
2022-03-01 05:53:24.016 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:nauticDawn#event triggered START
2022-03-01 06:29:28.025 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:nauticDawn#event triggered END
2022-03-01 06:29:28.027 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:civilDawn#event triggered START
2022-03-01 07:00:23.232 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:rise#event triggered START
2022-03-01 07:00:23.233 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:civilDawn#event triggered END
2022-03-01 07:03:31.447 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:rise#event triggered END
2022-03-01 07:03:31.450 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:daylight#event triggered START
2022-03-01 17:58:00.003 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:set#event triggered START
2022-03-01 17:58:00.006 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:daylight#event triggered END
2022-03-01 18:01:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:set#event triggered END
2022-03-01 18:01:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:civilDusk#event triggered START
2022-03-01 18:33:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:civilDusk#event triggered END
2022-03-01 18:33:00.004 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:nauticDusk#event triggered START
2022-03-01 19:09:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:nauticDusk#event triggered END
2022-03-01 19:09:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:astroDusk#event triggered START
2022-03-01 19:45:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:eveningNight#event triggered START
2022-03-01 19:45:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:night#event triggered START
2022-03-01 19:45:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:dahoam:astroDusk#event triggered END

Maybe it is not important, but it is interesting, that the order of the events which are happening at the same time is not always the same.

[rossko57]

@usambara

the order of the events which are happening at the same time is not always the same

Just reflects the asynchronous nature of both openHAB event bus and the logging mechanism itself.

Missing events looked into before often come down to a function of latitude.

[usambara (Ulrich)]

I’ve reprogrammed my astro stuff and replaced all the channel triggers like these
@when("Channel 'astro:sun:dahoam:civilDusk#event' triggered START")
by
ScriptExecution.createTimer(NightStart, lambda: fnNightStartTimer())
where NightStart is fetched with getEventTime() from the Astro-binding.
That seems to work reliable.

But while searching for the root cause, I have seen that the behaviour claimed in the original post was dependent of the uptime of OH.

I could see that not only the astro binding is affected but also others, like systeminfo and network and maybe others I haven’t identified so far.

It seems to me that the OH internal timers are getting mad. The actualization intervals are getting longer and longer. After the restart of OH it works fine again but it is again increasing.

The picture illustrates the long interval (4 days after last restart). After the restart it is fast again, but starts to increase.

I’m not sure when that started as I had many restarts the last weeks, but I assume it was with 3.3.0.M1.

[BigGeorgeTx (George M Hyde)]

I have experienced the same problem: Astro Binding Triggers Stop Working

An event is not triggered, with no explanation and no error. I restart openHAB and it works for a while, then it happens again. I just installed a clean new openhabian and openHAB 3.3M2 on a separate Pi with only a couple of bindings. I’m using it to control critical functions (like turning on the outside lighting at dusk). I’m going to see if it is more reliable than my full system.

[rossko57]

Astro binding relies on system scheduler to fire its events. It sounds like you have something else gobbling up scheduler execution threads, which as you observe would also cause many other features to grind to a halt.
You’d get similar symptoms from running out of memory (as scheduled work cannot be started) but there’s usually more definite “out of memory” messages. You’ve looked for those?

[usambara (Ulrich)]

I have no out of memory messages found in my system.

But I still can imagine that there is a relation to the systeminfo binding:

Error message during start-up after updating from 3.1.1 to 3.2: [core.karaf.internal.FeatureInstaller] - Failed installing add-ons

Merry Xmas to all ! Unforturnately, I have an issue after updating from OH3.1.1 to OH3.2 via Openhabian (RPi4). I get following error message during start-up: [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing ‘openhab-persistence-mapdb, openhab-binding-mail, openhab-transformation-javascript, openhab-binding-network, openhab-persistence-influxdb, openhab-ui-habpanel, openhab-binding-zwave, openhab-binding-netatmo, openhab-ui-basic, openhab-binding-openweathermap, openhab-bindi…

After many restarts the binding did start without obvious side effects.
I have it uninstalled now and will see what will happen. But the uninstall of the binding also led to several restarts of OH, what I haven’t observed with any other binding since my first installation with OH (that was 1.8…).