[Solved with workaround] openHAB2 Astro binding issue

scottk · October 8, 2016, 8:37pm

I’m new to openHAB, so I’m still learning the ropes here.

I am running openHAB2 on a Raspberry Pi 3 under openHABian – thank you @ThomDietrich! So far as I know, no problems with my installation.

I have been playing with the Astro binding for openHAB2, trying out some of the recently posted examples of time of day rules. After sorting out some java issues in my rules, I have what seems to be a good configuration with the exception of the items linked to the channels astro::home:position#". Sometimes those items are updated every 60 seconds, as expected, but most of the time the astro position items are updated once at system startup and never again.

Digging into the source to try to track my problem down, I see that the periodic update jobs for items linked to astro positional channels are only scheduled if linkedPositionalChannels > 0. In the logs I always see log entries from within the same job scheduling block for the astro daily jobs, but rarely do I see any log entries for the positional jobs. I suspect that there must be a race condition between the execution of the AstroThingHandler job scheduling and the binding-external calls to the method channelLinked.

Has anyone else encountered this issue? If not, can anyone offer any ideas as to what I am doing that causes this behavior?

Thanks in advance for any help or insight you might provide.

For reference, the relevant excerpt from my things configuration:

astro:sun:home          [ geolocation="35.717772,-105.903295", interval=60 ]
astro:moon:home         [ geolocation="35.717772,-105.903295", interval=60 ]

… from my items:

// Astro Items:
Number SunAzimuth	"Sun Azimuth"		<sun>	{ channel="astro:sun:home:position#azimuth" }
Number SunElevation	"Sun Elevation"		<sun>	{ channel="astro:sun:home:position#elevation" }

Number MoonAzimuth	"Moon Azimuth"		<moon>	{ channel="astro:moon:home:position#azimuth" }
Number MoonElevation	"Moon Elevation"		<moon>	{ channel="astro:moon:home:position#elevation" }

… from my rules:

val String TODR = "time-of-day.rules"

rule "Update SunIsUp_State"
when
    Item SunElevation changed
then
    try {
        logInfo(TODR, "SunElevation changed from {} to {}", previousState, SunElevation.state)

        //ChangeItemState.apply(TODR, SunIsUp_State, SunElevation.state >  0 ? ON : OFF)
        if (SunElevation.state >  0) {
            if (SunIsUp_State.state != ON) {
                SunIsUp_State.postUpdate(ON)
                logInfo(TODR, "SunIsUp_State.postUpdate(ON)")
            }
        } else {
            if (SunIsUp_State.state != OFF) {
                SunIsUp_State.postUpdate(OFF)
                logInfo(TODR, "SunIsUp_State.postUpdate(OFF)")
            }
        }
    } catch (Throwable t) {
        logError(TODR, "Exception in 'Update SunIsUp_State' rule: {}", t.toString())
    }
end

… from openhab.log:

2016-10-08 13:02:09.535 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - Locale set to en_US_#Latn
2016-10-08 13:02:14.396 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
2016-10-08 13:02:14.676 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2016-10-08 13:02:17.388 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'time-of-day.rules'
2016-10-08 13:02:19.696 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
2016-10-08 13:02:20.124 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.things'
2016-10-08 13:02:20.180 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2016-10-08 13:02:22.572 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-10-08 13:02:23.001 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-10-08 13:02:23.223 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-10-08 13:02:23.365 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-10-08 13:02:23.457 [ERROR] [org.eclipse.smarthome.io.javasound  ] - [org.eclipse.smarthome.io.javasoundsource(158)] Error during instantiation of the implementation object
java.lang.RuntimeException: Error creating the AudioSource
...
2016-10-08 13:02:26.759 [DEBUG] [ding.astro.handler.AstroThingHandler] - stopJobs
2016-10-08 13:02:26.807 [DEBUG] [ding.astro.handler.AstroThingHandler] - stopJobs
2016-10-08 13:02:26.822 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:moon:home
2016-10-08 13:02:26.826 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:home
2016-10-08 13:02:26.828 [DEBUG] [g.astro.internal.job.AbstractBaseJob] - Starting astro DailyJob for thing astro:moon:home
2016-10-08 13:02:26.852 [DEBUG] [g.astro.internal.job.AbstractBaseJob] - Starting astro DailyJob for thing astro:sun:home
2016-10-08 13:02:26.895 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:home
2016-10-08 13:02:26.910 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:home
2016-10-08 13:02:30.076 [INFO ] [thome.model.script.time-of-day.rules] - Setting period of day at system startup. now: 2016-10-08T13:02:29.868-06:00
2016-10-08 13:02:30.087 [INFO ] [thome.model.script.time-of-day.rules] - Initializing period of day. Period of day: Day, 2016-10-08T13:02:30.079-06:00
2016-10-08 13:02:30.095 [INFO ] [thome.model.script.time-of-day.rules] - --> SunIsUp_State init
2016-10-08 13:02:30.107 [INFO ] [thome.model.script.time-of-day.rules] - --> SunIsUp_State ON
2016-10-08 13:03:24.931 [INFO ] [thome.model.script.time-of-day.rules] - Checking for period of day change. Period of day: Day, 2016-10-08T13:03:24.921-06:00
2016-10-08 13:04:24.922 [INFO ] [thome.model.script.time-of-day.rules] - Checking for period of day change. Period of day: Day, 2016-10-08T13:04:24.910-06:00

… and finally from events.log:

2016-10-08 13:02:19.939 [ItemChannelLinkAddedEvent ] - Link 'CurrentTime-ntp:ntp:local:dateTime' has been added.
2016-10-08 13:02:19.946 [ItemChannelLinkAddedEvent ] - Link 'DawnStart_Time-astro:sun:home:civilDawn#start' has been added.
2016-10-08 13:02:19.949 [ItemChannelLinkAddedEvent ] - Link 'DayStart_Time-astro:sun:home:daylight#start' has been added.
2016-10-08 13:02:19.951 [ItemChannelLinkAddedEvent ] - Link 'DuskStart_Time-astro:sun:home:civilDusk#start' has been added.
2016-10-08 13:02:19.953 [ItemChannelLinkAddedEvent ] - Link 'NightStart_Time-astro:sun:home:night#start' has been added.
2016-10-08 13:02:19.954 [ItemChannelLinkAddedEvent ] - Link 'SunriseStart_Time-astro:sun:home:rise#start' has been added.
2016-10-08 13:02:19.956 [ItemChannelLinkAddedEvent ] - Link 'SunriseEnd_Time-astro:sun:home:rise#end' has been added.
2016-10-08 13:02:19.957 [ItemChannelLinkAddedEvent ] - Link 'SunsetStart_Time-astro:sun:home:set#start' has been added.
2016-10-08 13:02:19.968 [ItemChannelLinkAddedEvent ] - Link 'SunsetEnd_Time-astro:sun:home:set#end' has been added.
2016-10-08 13:02:19.970 [ItemChannelLinkAddedEvent ] - Link 'SunAzimuth-astro:sun:home:position#azimuth' has been added.
2016-10-08 13:02:19.971 [ItemChannelLinkAddedEvent ] - Link 'SunElevation-astro:sun:home:position#elevation' has been added.
2016-10-08 13:02:19.973 [ItemChannelLinkAddedEvent ] - Link 'MoonAzimuth-astro:moon:home:position#azimuth' has been added.
2016-10-08 13:02:19.974 [ItemChannelLinkAddedEvent ] - Link 'MoonElevation-astro:moon:home:position#elevation' has been added.
2016-10-08 13:02:19.975 [ItemChannelLinkAddedEvent ] - Link 'MoonPhase-astro:moon:home:phase#name' has been added.
2016-10-08 13:02:23.775 [ThingAddedEvent           ] - Thing 'astro:sun:home' has been added.
2016-10-08 13:02:23.778 [ThingAddedEvent           ] - Thing 'astro:moon:home' has been added.
2016-10-08 13:02:23.846 [ThingAddedEvent           ] - Thing 'ntp:ntp:local' has been added.
2016-10-08 13:02:23.990 [hingStatusInfoChangedEvent] - 'astro:sun:home' changed from UNINITIALIZED to INITIALIZING
2016-10-08 13:02:23.995 [hingStatusInfoChangedEvent] - 'astro:moon:home' changed from UNINITIALIZED to INITIALIZING
2016-10-08 13:02:24.030 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from UNINITIALIZED to INITIALIZING
2016-10-08 13:02:24.098 [hingStatusInfoChangedEvent] - 'astro:sun:home' changed from INITIALIZING to ONLINE
2016-10-08 13:02:24.111 [hingStatusInfoChangedEvent] - 'astro:moon:home' changed from INITIALIZING to ONLINE
2016-10-08 13:02:24.122 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from INITIALIZING to ONLINE
2016-10-08 13:02:24.145 [ItemStateChangedEvent     ] - CurrentTime changed from NULL to 2016-10-08T13:02:24.082-0600
2016-10-08 13:02:24.795 [ThingUpdatedEvent         ] - Thing 'astro:sun:home' has been updated.
2016-10-08 13:02:24.888 [ThingUpdatedEvent         ] - Thing 'astro:moon:home' has been updated.
2016-10-08 13:02:24.901 [ThingUpdatedEvent         ] - Thing 'ntp:ntp:local' has been updated.
2016-10-08 13:02:24.911 [ItemStateChangedEvent     ] - CurrentTime changed from 2016-10-08T13:02:24.082-0600 to 2016-10-08T13:02:24.893-0600
2016-10-08 13:02:26.907 [ItemStateChangedEvent     ] - MoonPhase changed from NULL to FIRST_QUARTER
2016-10-08 13:02:26.913 [ItemStateChangedEvent     ] - MoonAzimuth changed from NULL to 108.16
2016-10-08 13:02:26.919 [ItemStateChangedEvent     ] - MoonElevation changed from NULL to -7.43
2016-10-08 13:02:26.927 [ItemStateChangedEvent     ] - SunriseStart_Time changed from NULL to 2016-10-08T07:06:00.000-0600
2016-10-08 13:02:26.934 [ItemStateChangedEvent     ] - SunriseEnd_Time changed from NULL to 2016-10-08T07:08:00.000-0600
2016-10-08 13:02:26.943 [ItemStateChangedEvent     ] - SunsetStart_Time changed from NULL to 2016-10-08T18:36:00.000-0600
2016-10-08 13:02:26.951 [ItemStateChangedEvent     ] - SunsetEnd_Time changed from NULL to 2016-10-08T18:38:00.000-0600
2016-10-08 13:02:26.958 [ItemStateChangedEvent     ] - NightStart_Time changed from NULL to 2016-10-08T20:03:00.000-0600
2016-10-08 13:02:26.967 [ItemStateChangedEvent     ] - DawnStart_Time changed from NULL to 2016-10-08T06:40:00.000-0600
2016-10-08 13:02:26.975 [ItemStateChangedEvent     ] - DuskStart_Time changed from NULL to 2016-10-08T18:38:00.000-0600
2016-10-08 13:02:26.982 [ItemStateChangedEvent     ] - DayStart_Time changed from NULL to 2016-10-08T07:08:00.000-0600
2016-10-08 13:02:26.985 [ItemStateChangedEvent     ] - SunAzimuth changed from NULL to 184.01
2016-10-08 13:02:26.988 [ItemStateChangedEvent     ] - SunElevation changed from NULL to 48.04
2016-10-08 13:02:29.860 [ItemStateChangedEvent     ] - PeriodOfDay_Str changed from NULL to Day
2016-10-08 13:02:29.864 [ItemStateChangedEvent     ] - PeriodOfDay_Str changed from Day to uninitialized
2016-10-08 13:02:29.869 [ItemStateChangedEvent     ] - SunIsUp_State changed from NULL to ON
2016-10-08 13:02:29.872 [ItemStateChangedEvent     ] - Dawn changed from NULL to OFF
2016-10-08 13:02:29.874 [ItemStateChangedEvent     ] - Day changed from NULL to ON
2016-10-08 13:02:29.876 [ItemStateChangedEvent     ] - Dusk changed from NULL to OFF
2016-10-08 13:02:29.894 [ItemStateChangedEvent     ] - Night changed from NULL to OFF
2016-10-08 13:02:29.896 [ItemStateChangedEvent     ] - DawnStart_Event changed from NULL to OFF
2016-10-08 13:02:29.897 [ItemStateChangedEvent     ] - DayStart_Event changed from NULL to ON
2016-10-08 13:02:29.900 [ItemStateChangedEvent     ] - DuskStart_Event changed from NULL to OFF
2016-10-08 13:02:29.902 [ItemStateChangedEvent     ] - NightStart_Event changed from NULL to OFF
2016-10-08 13:02:30.102 [ItemStateChangedEvent     ] - PeriodOfDay_Str changed from uninitialized to Day
2016-10-08 13:03:24.906 [ItemStateChangedEvent     ] - CurrentTime changed from 2016-10-08T13:02:24.893-0600 to 2016-10-08T13:03:24.884-0600
2016-10-08 13:04:24.904 [ItemStateChangedEvent     ] - CurrentTime changed from 2016-10-08T13:03:24.884-0600 to 2016-10-08T13:04:24.884-0600
2016-10-08 13:05:24.907 [ItemStateChangedEvent     ] - CurrentTime changed from 2016-10-08T13:04:24.884-0600 to 2016-10-08T13:05:24.884-0600

MikeD · October 8, 2016, 10:07pm

There is an issue with astro positional jobs not starting reliably after a restart of openHAB 2.

The way I get around this is to uninstall then reinstall the Astro binding from the paper UI after a restart. Every time I do this the positional jobs start and then run correctly.

The problem has been reported so hopefully there will be a fix soon.

Hope the above helps.

scottk · October 8, 2016, 10:12pm

Bingo! That did help.

Just as you said, Mike, [quote=“MikeD, post:2, topic:15006”]
…uninstall then reinstall the Astro binding from the paper UI after a restart.
[/quote]

Thank you for the workaround, @MikeD!

RHINESEL · October 9, 2016, 2:17am

Out of curiosity, why not just run the 1.9 version of the binding? Many are doing this until sunrise/sunset capabilities are built into OH2.

scottk · October 9, 2016, 2:51pm

Matthew,

I just haven’t gotten around to trying out the 1.x Astro binding with OH2. That’s primarily because the demo config uses the OH2 Astro binding. Also, when I searched for Astro bindings in the karaf console, the only binding listed is the OH2 binding.

SK

RHINESEL · October 9, 2016, 6:01pm

1.9 binding is very easy. Install via Paper UI. It will auto generate a Astro.cfg file in your services folder. Just update the file with your lat/long and you’re ready to go. You can make a switch item that switches based on sunset/sunrise and then use them in your rules. Examples are on the Astro binding wiki. Takes about 5 minutes to set up.

rlkoshak · October 10, 2016, 5:01pm

You need to enable “Show legacy 1.9 bindings” in Configuration > System for PaperUI to show the 1.9 version of bindings that have a 2.0 version. I’m not sure how to make that setting in the console.

scottk · October 10, 2016, 5:28pm

Thanks for the pointer, @rlkoshak. I found that setting when I revisited the PaperUI looking for something I had missed in my configuration. Hopefully the next person to start exploring openHAB2 and the Astro binding can find all information required for getting the Astro 1.9 binding going in this thread.

Cheers!