Astro-Binding: all events are triggered at the same time shortly after midnight

Hi,

I have a problem with the Astro-Binding.
Until about two weeks ago the Binding was running without a problem. But lately I have the problem that, after a reboot of the Raspberry Pi running OpenHab (currently 2.5.3), the binding only generates correct events for one and a half days and thereafter generates all events shortly after midnight on all successive days.

Any ideas on how to further investigate this behavior (debug settings etc.). I would assume that this is a PEBKAC or does anyone else have this problem?

There are no errors or warnings related to this in the openhab.log.

I only use the astro:sun:local:set event to trigger a rule to close the window shades.

Here is an excerpt from the events.log:

Binding started after reboot

2020-04-26 23:22:19.529 [thome.event.ExtensionEvent] - Extension 'binding-astro' has been installed.

First day all events at the correct times (for Darmstadt, Germany)

2020-04-27 00:00:30.834 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START
2020-04-27 00:14:00.003 [vent.ChannelTriggeredEvent] - astro:moon:local:set#event triggered END
2020-04-27 03:55:59.277 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered END
2020-04-27 03:55:59.282 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered START
2020-04-27 04:48:59.275 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered END
2020-04-27 04:48:59.278 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered START
2020-04-27 05:33:59.275 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered START
2020-04-27 05:33:59.278 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered END
2020-04-27 06:09:59.275 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered START
2020-04-27 06:09:59.279 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered END
2020-04-27 06:13:59.277 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered END
2020-04-27 06:13:59.282 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered START
2020-04-27 08:41:59.277 [vent.ChannelTriggeredEvent] - astro:moon:local:rise#event triggered START
2020-04-27 13:23:59.276 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered START
2020-04-27 13:24:59.276 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered END
2020-04-27 20:34:59.277 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2020-04-27 20:34:59.282 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered END
2020-04-27 20:37:59.277 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered START
2020-04-27 20:37:59.294 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered END
2020-04-27 21:13:59.277 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered START
2020-04-27 21:13:59.282 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered END
2020-04-27 21:58:59.277 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered START
2020-04-27 21:58:59.282 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered END
2020-04-27 22:51:59.277 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered END
2020-04-27 22:51:59.283 [vent.ChannelTriggeredEvent] - astro:sun:local:night#event triggered START
2020-04-27 22:51:59.287 [vent.ChannelTriggeredEvent] - astro:sun:local:eveningNight#event triggered START

On the second day all events are OK until “astro:sun:local:civilDusk#event triggered START”

2020-04-28 00:00:30.163 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START
[...skipped...]
2020-04-28 20:36:00.002 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered END
2020-04-28 20:36:00.004 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2020-04-28 20:40:00.007 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered END
2020-04-28 20:40:00.012 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered START

But the END event is triggered much later, 30 seconds after midnight.
And all other events following civilDusk are also triggered at that time:

2020-04-29 00:00:30.260 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered END
2020-04-29 00:00:30.263 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered START
2020-04-29 00:00:30.268 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered END
2020-04-29 00:00:30.271 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered START
2020-04-29 00:00:30.275 [vent.ChannelTriggeredEvent] - astro:sun:local:eveningNight#event triggered START
2020-04-29 00:00:30.279 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered END
2020-04-29 00:00:30.282 [vent.ChannelTriggeredEvent] - astro:sun:local:night#event triggered START
2020-04-29 00:00:30.285 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START

No further events were triggerd on the 29th. On the 30th (and also on the 1st of May) all ASTRO event were triggered at the same time, again 30 seconds after midnight.

2020-04-30 00:00:30.430 [vent.ChannelTriggeredEvent] - astro:moon:local:set#event triggered END
2020-04-30 00:00:30.434 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered END
2020-04-30 00:00:30.437 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered START
2020-04-30 00:00:30.441 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered END
2020-04-30 00:00:30.449 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered START
2020-04-30 00:00:30.455 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered START
2020-04-30 00:00:30.464 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDawn#event triggered END
2020-04-30 00:00:30.469 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered START
2020-04-30 00:00:30.473 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDawn#event triggered END
2020-04-30 00:00:30.477 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered START
2020-04-30 00:00:30.481 [vent.ChannelTriggeredEvent] - astro:sun:local:rise#event triggered END
2020-04-30 00:00:30.486 [vent.ChannelTriggeredEvent] - astro:moon:local:rise#event triggered START
2020-04-30 00:00:30.490 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered START
2020-04-30 00:00:30.494 [vent.ChannelTriggeredEvent] - astro:sun:local:noon#event triggered END
2020-04-30 00:00:30.497 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered START
2020-04-30 00:00:30.501 [vent.ChannelTriggeredEvent] - astro:sun:local:daylight#event triggered END
2020-04-30 00:00:30.504 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered START
2020-04-30 00:00:30.508 [vent.ChannelTriggeredEvent] - astro:sun:local:set#event triggered END
2020-04-30 00:00:30.512 [vent.ChannelTriggeredEvent] - astro:sun:local:civilDusk#event triggered END
2020-04-30 00:00:30.516 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered START
2020-04-30 00:00:30.519 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered START
2020-04-30 00:00:30.525 [vent.ChannelTriggeredEvent] - astro:sun:local:nauticDusk#event triggered END
2020-04-30 00:00:30.527 [vent.ChannelTriggeredEvent] - astro:sun:local:night#event triggered START
2020-04-30 00:00:30.530 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDusk#event triggered END
2020-04-30 00:00:30.534 [vent.ChannelTriggeredEvent] - astro:sun:local:eveningNight#event triggered START
2020-04-30 00:00:30.537 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START

Here is the rule that uses the sunset event:

rule "Sunset Rule"
when
    Channel 'astro:sun:local:set#event' triggered END
then
        logInfo("Regular_Automation", "Sunset: Alle Rollos schliessen")
        KNX_EGWohnenJalLi.sendCommand(DOWN)
        KNX_EGWohnenJalRe.sendCommand(DOWN)
end

This rule is triggered, but also only at midnight when the event is generated.

2020-04-27 20:38:00.449 [INFO ] [home.model.script.Regular_Automation] - Sunset: Alle Rollos schliessen
2020-04-30 00:00:30.519 [INFO ] [home.model.script.Regular_Automation] - Sunset: Alle Rollos schliessen
2020-05-01 00:00:30.670 [INFO ] [home.model.script.Regular_Automation] - Sunset: Alle Rollos schliessen

Any ideas or suggestions are appreciated.
Best regards,

Thomas

Has been reported before, from time to time.

The most surprising guilty culprit was logreader binding. Do you have that?

The problem was logreader tied up shared scheduling resources. (Correlates with your observation that it takes a couple of days). I would imagine there are other ways to also do that, and give the same symptom as far as Astro is concerned.

1 Like

No, I do not have the logreader binding installed. Currently I have only the following add-ons:

  • Astro Binding

  • HarmonyHub Binding

  • KNX Binding

  • Samsung TV Binding

  • InfluxDB (v 1.0) Persistence

  • Basic UI

  • Classic UI

  • Dashboard UI

  • HABmin

  • HABPanel

  • Home Builder

  • Paper UI

Looking at the Bug Report you referenced and using the threads --locks --monitors console command mentioned therein I found a suspiciously large number of HarmonyDiscoveryServer threads in a blocked state (about 50 threads)

"HarmonyDiscoveryServer(tcp/46399)" Id=1469 in BLOCKED on lock=org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl@1a73a3c
     owned by upnp-main-134 Id=1294

upnp-main-134 was also blocked by a lock from ESH-httpclient-samtungtv[sic]

"upnp-main-134" Id=1294 in BLOCKED on lock=java.lang.Object@8d988t
     owned by ESH-httpClient-samtungtv-316 Id=316

The samtung-316 thread was waiting for something…

"ESH-httpClient-samtungtv-316" Id=316 in WAITING on lock=java.util.concurrent.CountDownLatch$Sync@1bc7200

Not sure if this is the cause of my problem, but will remove the HarmonyHub and SamsungTV bindings to see if this helps. This might take a while to check…

1 Like

Well, after three days everything is still running smoothly, with all Astro events right on time and no blocked threads.
So I guess the culprit was either the SamsungTV or the HarmonyHub binding (or some interaction between them). As I don’t really need either of these bindings at the moment I will leave it at that.

@rossko57: thank you for pointing in the right direction.

brgds

1 Like