openhab-addons: [astro] Events scheduled but not triggered 2.5

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"