Astro Binding - Events scheduled but not triggered

LukasA · December 13, 2019, 3:51pm

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.

Following steps I did to reproduce the issue / ensure it is not related to another issue:

Openhab 2.5.RC1 fresh install a docker (compose) stack (AMD64 architecture), see configuration below
Items and Sitemaps copied across
No other json db restored
Installed all used addons (ASTRO, LCN, TELEGRAM, DECONZ, MAIL BINDING, NEXT GEN RULES)

When adding a new ASTRO thing, the events are triggered. After updating one ranged event channel, in my case sun:rise, with earliest & latest times, I see in the event log ASTRO schedules the event, see log below, but no event is triggered at the same time.

Is something wrong with my configuration or is there any bug in the ASTRO binding? I couldn’t find anything related by using the search.

Docker:

    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"

Log:

2019-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)
2019-12-13 09:26:01.759 [DEBUG] [o.internal.handler.AstroThingHandler] - Thing astro:sun:local initialized ONLINE

rlkoshak · December 13, 2019, 4:47pm

There won’t be an event triggered at the same time. The event will be triggered at the scheduled time. For example, based on your log, you should see an event on the astro:sun:local:rise#event at 2019-12-13T09:30:00. Do you mean that they are not triggering at the scheduled time?

LukasA · December 13, 2019, 4:58pm

Thanks for quick reply.
The event is not triggered at the time it should, e.g. 9:30.
Instead all these events will trigger adter midnight, or, after updating the ranged event (e.g. modifying the offset)

rossko57 · December 13, 2019, 5:17pm

Would you show us your events.log for this after midnight flurry?

rlkoshak · December 13, 2019, 5:20pm

How are you looking for/verifying that the events are or are not occurring? Do you have Rules that should trigger on the sun events?

I expect to see all those scheduling log statements 30 seconds after midnight every day. That is when Astro schedules the Thing Channel Trigger Event to occur. But those are not events (i.e. you don’t see them in events.log). At the scheduled time for each Trigger you should see a ChannelTriggeredEvent from that Channel in events.log and if you have a Rule triggered by that event, the Rule should run. It’s not clear to me how you are looking for/verifying whether or not the schedule event occurs.

If you are using a Rule, please show that Rule.

LukasA · December 13, 2019, 5:40pm

I realized the issue because rules haven’t been triggered by ASTRO binding and traced it via events.log. CRON trigger work as expect.
For the test container I removed all rules (not imported them) to make sure those are not related to my issue.

In my 2.5 M3 I have these kind of lines in events.log:
2019-12-12 06:24:57.014 [vent.ChannelTriggeredEvent] - astro:sun:local:astroDawn#event triggered START

In 2.5 RC1 there is no such line. I don’t have the logs from midnight because I did a last try with a fresh docker container, but it’s bascially showing at 00:00:30.xxx many lines with events triggering START and END.

One observation I made: If I change the offset of one channel so that it should trigger in 1 or 2 minutes (for testing) it worked, anything longer than that did not.

rlkoshak · December 13, 2019, 5:47pm

OK, we will probably need to see those logs unfortunately. And this looks like a bug of some sort so How to file an Issue on the openhab2-addons repo will probably be required. But they will almost certainly require the full set of logs and your Thing definitions.

I don’t use Astro Channel events any more so I wouldn’t have noticed this issue.

LukasA · December 13, 2019, 7:31pm

Done, thanks for your help.

rlkoshak · December 13, 2019, 8:48pm

A link to the issue would be useful for other users who happen upon this thread.

John_Siemon · December 13, 2019, 9:56pm

FWIW I am running RC1 with Astro and my rules with Astroevent triggers are working fine. Xmas lights go on at sunset and house/land perimeter lights go on/off at sunset/sunrise.

when
    Channel "astro:sun:fee0abb8:set#event" triggered 

when
  Channel "astro:sun:fee0abb8:rise#event" triggered

LukasA · December 14, 2019, 8:53am

Link to issue