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

innot · May 1, 2020, 11:48am

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

rossko57 · May 1, 2020, 1:08pm

Has been reported before, from time to time.

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

github.com/openhab/openhab-addons

[astro] Events scheduled but not triggered 2.5

opened 07:29PM - 13 Dec 19 UTC

closed 05:49PM - 23 Dec 19 UTC

LukasA83

bug

## Expected Behavior After upgrading from 2.5 M3 to RC1 (basically since M4) I’…m struggeling with the Astro binding. In the log I see the events being scheduled, but these are not triggered. Whenever I do an update to the Astro thing or after midnite, I see the events are triggered in the logs. Usually I see the ASTRO events triggered in events.log, like this: 2019-12-12 00:00:30.123 [vent.ChannelTriggeredEvent] - astro:sun:local:morningNight#event triggered START ## Current Behavior Since upgrade I see events being scheduled in openhab.log, but no event triggering in events.log. ``` 019-12-13 09:26:01.678 [DEBUG] [o.internal.handler.AstroThingHandler] - Restarting jobs for thing astro:sun:local 2019-12-13 09:26:01.681 [DEBUG] [o.internal.handler.AstroThingHandler] - Stopping scheduled jobs for thing astro:sun:local 2019-12-13 09:26:01.689 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled org.eclipse.smarthome.core.internal.scheduler.SchedulerImpl$ScheduledCompletableFutureRecurring@6331744a[Not completed, 2 dependents] at midnight 2019-12-13 09:26:01.703 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:local 2019-12-13 09:26:01.706 [INFO ] [enhab.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local 2019-12-13 09:26:01.708 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/rise#event/START + Event job astro:sun:local/rise#event/END in 238292ms (at 2019-12-13T09:30:00) 2019-12-13 09:26:01.711 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/START in 24778290ms (at 2019-12-13T16:19:00) 2019-12-13 09:26:01.713 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/set#event/END in 25018288ms (at 2019-12-13T16:23:00) 2019-12-13 09:26:01.715 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/START in 10798286ms (at 2019-12-13T12:26:00) 2019-12-13 09:26:01.717 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/noon#event/END in 10858283ms (at 2019-12-13T12:27:00) 2019-12-13 09:26:01.719 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/night#event/START in 32458281ms (at 2019-12-13T18:27:00) 2019-12-13 09:26:01.722 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/START in 29998278ms (at 2019-12-13T17:46:00) 2019-12-13 09:26:01.724 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/astroDusk#event/END in 32458276ms (at 2019-12-13T18:27:00) 2019-12-13 09:26:01.725 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/START in 27418275ms (at 2019-12-13T17:03:00) 2019-12-13 09:26:01.727 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/nauticDusk#event/END in 29998273ms (at 2019-12-13T17:46:00) 2019-12-13 09:26:01.729 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/START in 25018271ms (at 2019-12-13T16:23:00) 2019-12-13 09:26:01.731 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/civilDusk#event/END in 27418269ms (at 2019-12-13T17:03:00) 2019-12-13 09:26:01.741 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/eveningNight#event/START in 32458259ms (at 2019-12-13T18:27:00) 2019-12-13 09:26:01.745 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Event job astro:sun:local/daylight#event/END in 24778255ms (at 2019-12-13T16:19:00) 2019-12-13 09:26:01.749 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/SUN_SET in 24778252ms (at 2019-12-13T16:19:00) 2019-12-13 09:26:01.750 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NIGHT in 32458250ms (at 2019-12-13T18:27:00) 2019-12-13 09:26:01.752 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/ASTRO_DUSK in 29998248ms (at 2019-12-13T17:46:00) 2019-12-13 09:26:01.754 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/NAUTIC_DUSK in 27418247ms (at 2019-12-13T17:03:00) 2019-12-13 09:26:01.755 [DEBUG] [o.internal.handler.AstroThingHandler] - Scheduled Sun phase job astro:sun:local/CIVIL_DUSK in 25018245ms (at 2019-12-13T16:23:00) ``` Expect to see astro event in events.log, e.g. rise start at 9:30, but it's not there: ``` 2019-12-13 09:27:42.331 [vent.ItemStateChangedEvent] - esszimmer_temp_ist changed from 21.5 to 21.4 2019-12-13 09:32:16.608 [vent.ItemStateChangedEvent] - warmwassertemp_lcnout changed from 49.4 to 49.3 ``` ## Possible Solution ## Steps to Reproduce (for Bugs) 1. Clean install, docker AMD64 Milestone build 2.5 RC1 2. Install Astro binding 3. Add one Astro thing 4. Change earliest / latest on one channel ## Context Since upgrade from M3 to (M4-RC) ASTRO binding stopped triggering my rules. So tracked it down to this reproducable situation, starting with a fresh docker installation. If I change the offset of a range event, so that it triggers within next 1 or 2 minutes, I see the event triggering in events.log, everything higher than 2 or 3 minutes and the event will not show up in events.log. ## Your Environment OpenHAB 2.5.RC1 Astro Binding Docker version 17.09.1-ce (linux/amd64) Docker compose: ``` version: '3' services: openhab_yaml: container_name: "openhab-yaml" image: "openhab/openhab:2.5.0.RC1" restart: always network_mode: bridge volumes: - "/etc/localtime:/etc/localtime:ro" - "/etc/timezone:/etc/timezone:ro" - "./openhab_addons:/openhab/addons" - "./openhab_conf:/openhab/conf" - "./openhab_userdata:/openhab/userdata" ports: - "50881:50880" - "50444:50443" - "5008:5007" - "50004:50003" environment: OPENHAB_HTTP_PORT: "50880" OPENHAB_HTTPS_PORT: "50443" EXTRA_JAVA_OPTS: "-Duser.timezone=Europe/Amsterdam" USER_ID: "9001" GROUP_ID: "9001" LC_ALL: "de_DE.UTF-8" LANG: "de_DE.UTF-8" LANGUAGE: "de_DE.UTF-8" CRYPTO_POLICY: "unlimited" ```

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.

innot · May 1, 2020, 10:21pm

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…

innot · May 4, 2020, 8:39pm

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