Openhab-addons: Daily jobs for astro binding don't seem to be running

[feens]

I've noticed that the only way I can seem to get the items linked to astro binding channels to actually update is if I remove and recreate the links. I'm using the latest version (as of yesterday, so 2016-03-10) of the binding.

I have two items: one is linked to the sunrise#start channel, and the other the sunset:start. If I exit OH and restart it, the state will be NULL. If I redo the linking, it will populate the values and indicate that that daily job is scheduled, however on the following day, the state will not have changed.

[feens]

@kaikreuzer I'm wondering if this it OH2/ESH related rather than binding related. I've also noticed that when I restart OH2 it doesn't schedule the daily jobs for the astro channels that I have linked unless I unlink/re-link them.

[kaikreuzer]

I would assume that it is a problem in the binding - at least that's the place where the analysis should start.

[feens]

While I may not be a Java developer, I have worked with Java (and who knows how many other languages), so I decided to at least dig through the source to see what I could find.

What I noticed is that in the binding, when there's a channel change, it runs the restartJobs(); method, which in turn schedules the daily job and immediate job to get the data. I also noticed that on the dispose() method it runs stopJobs(). Extrapolating from this, I would expect that the initializer _should_ also start the jobs (using restartJobs()) but that piece seems to be missing. I'm guessing it belongs after line 93 here: https://github.com/openhab/openhab2-addons/blob/master/addons/binding/org.openhab.binding.astro/src/main/java/org/openhab/binding/astro/handler/AstroThingHandler.java

I don't have the whole ESH IDE setup so I can't test or submit a PR, but imagine that's a relatively simple change to make.

[feens]

One other thing I noticed while testing: if the Item is NULL, and I try and refresh, it throws an error. I suspect it's an ESH issue, not a binding issue, but here is the message in full:

18:12:34.694 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while calling handler: java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_65]
    at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_65]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:179)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:72)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:56)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.receiveCommand(ThingManager.java:344)[95:org.eclipse.smarthome.core.thing:0.8.0.201603141848]
    at org.eclipse.smarthome.core.items.events.AbstractItemEventSubscriber.receive(AbstractItemEventSubscriber.java:46)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:192)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:1)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:170)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
    at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
Caused by: java.lang.NullPointerException
    at org.openhab.binding.astro.handler.AstroThingHandler.publishChannelIfLinked(AstroThingHandler.java:144)[154:org.openhab.binding.astro:2.0.0.201603210202]
    at org.openhab.binding.astro.handler.AstroThingHandler.handleCommand(AstroThingHandler.java:115)[154:org.openhab.binding.astro:2.0.0.201603210202]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$2.call(ThingManager.java:347)[95:org.eclipse.smarthome.core.thing:0.8.0.201603141848]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$2.call(ThingManager.java:1)[95:org.eclipse.smarthome.core.thing:0.8.0.201603141848]
    ... 5 more
18:12:34.722 [ERROR] [ding.astro.handler.AstroThingHandler] - Can't update state for channel astro:sun:5864fb96:rise#start: null
java.lang.NullPointerException
    at org.openhab.binding.astro.internal.util.PropertyUtils.getPropertyValue(PropertyUtils.java:65)[154:org.openhab.binding.astro:2.0.0.201603210202]
    at org.openhab.binding.astro.internal.util.PropertyUtils.getPropertyValue(PropertyUtils.java:56)[154:org.openhab.binding.astro:2.0.0.201603210202]
    at org.openhab.binding.astro.internal.util.PropertyUtils.getState(PropertyUtils.java:35)[154:org.openhab.binding.astro:2.0.0.201603210202]
    at org.openhab.binding.astro.handler.AstroThingHandler.publishChannelIfLinked(AstroThingHandler.java:146)[154:org.openhab.binding.astro:2.0.0.201603210202]
    at org.openhab.binding.astro.handler.AstroThingHandler.handleCommand(AstroThingHandler.java:115)[154:org.openhab.binding.astro:2.0.0.201603210202]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$2.call(ThingManager.java:347)[95:org.eclipse.smarthome.core.thing:0.8.0.201603141848]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$2.call(ThingManager.java:1)[95:org.eclipse.smarthome.core.thing:0.8.0.201603141848]
    at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:170)[89:org.eclipse.smarthome.core:0.8.0.201603141848]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
    at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]

[kaikreuzer]

Well, the NPEs are thrown in org.openhab.binding.astro.handler.AstroThingHandler.publishChannelIfLinked(AstroThingHandler.java:144) and org.openhab.binding.astro.internal.util.PropertyUtils.getPropertyValue(PropertyUtils.java:65), so I would claim the bug is in the binding.

[kaikreuzer]

@gerrieg Could you have a look at this, please?

[gerrieg]

I can not reproduce the behavior... I've tested with the latest code from the GIT repos and with some thing/item configs. Values are always published after a restart.

@feens
So which exact OH version are you using? Also post your astro thing and item files please.

[toneus]

I too am experiencing where the Astro binding fails to run after a reboot. Deleting and re-Linking will return the Astro binding to normal service. Seems as if the scheduling is not reinitialized after a reboot.

I'll try to assist where I can.

I am running OH2 Beta 2.

Tony

[Woutch]

Hello, I have the same Issue, everything still "null", until I change a link or channel. I also have the problem that only the midnight job runs. And not the "refresh" job that is configurable in the thing. (Default 300 sec). So channels like Sun Elevation only get updated at midnight, but this is continuously changing. (I have a rule based on this value)

If you want any input, please ask, I'll do what I can to help you. (This is blocking my migration from OH1 to OH2).

Running the latest openhab (online) snapshot from this night.

Wouter

[feens]

@gerrieg did you happen to look at my previous comment? I'm pretty sure I identified where the issue is in the code (i.e. the initialize method isn't calling restartJobs).

[gerrieg]

yes, i read your comment. I still can not reproduce this, but i've added restartJobs() now in line 93. Maybe this fixes your problem. The NullPointer is also fixed with https://github.com/openhab/openhab2-addons/pull/1079

[kaikreuzer]

Fixed by https://github.com/openhab/openhab2-addons/pull/1079

[mattti]

I have a very similar problem, that i believe might be connected to the issue.

Items:

Number   Azimuth       "Azimuth"                (gAtmo) { channel="astro:sun:home:position#azimuth" }
Number   Elevation     "Elevation"              (gAtmo) { channel="astro:sun:home:position#elevation" }

Things:

astro:sun:home  [ geolocation="XX.XXXXXX,X.XXXXXX", interval=60 ]
astro:moon:home  [ geolocation="XX.XXXXXX,X.XXXXXX", interval=60 ]

After relinking the items, they get updated every minute as expected. The log shows:

2016-10-25 14:32:49.679 [INFO ] [ding.astro.handler.AstroThingHandler] - Deleting astro DailyJob for thing 'astro:sun:home'
2016-10-25 14:32:49.680 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:home
2016-10-25 14:32:49.681 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro PositionalJob with interval of 60 seconds for thing astro:sun:home
2016-10-25 14:32:49.738 [INFO ] [ding.astro.handler.AstroThingHandler] - Deleting astro DailyJob for thing 'astro:moon:home'
2016-10-25 14:32:49.739 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:moon:home
2016-10-25 14:32:49.739 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro PositionalJob with interval of 60 seconds for thing astro:moon:home

However, after a restart, the items get updated only once and the 60s jobs are not created:

2016-10-25 14:55:22.261 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:home
2016-10-25 14:55:22.270 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:moon:home

The only thing that helps, seems to be relinking of the items.
I'm on build 555.

[gerrieg]

This should be fixed with https://github.com/openhab/openhab2-addons/pull/1178
I don't know if this fix is included in build 555. Maybe you try the latest astro binding build and give me feedback?

[mattti]

I'm using the latest OH2 from the Snapshot repo.
I get the following Astro version from karaf:
2.0.0.201610221219
#1178 should be included in that build.
I also don't see "Unable to store Job" Error on startup.
If you think it'll make a difference, however, I'll build the latest.

[gerrieg]

OK, i can reproduce. But in the development environment it works. It does not work when i download the latest snapshot and start it via command line.
I'll let you know when I've found something

[gerrieg]

Problem found, will update the binding in the next days.

[gerrieg]

fixed with https://github.com/openhab/openhab2-addons/pull/1356

[mattti]

It works now for me.
Many thanks for your work!!!