[SOLVED] Astro binding problem - events do not trigger (multiple triggers solved)

I had posted my issues with the Astro binding scheduler here . In the meantime I cleaned up all links from old configs as suggested, created a new channel, items and rules.
The result is that now:

  • the channels only fire on the day I started OH2, but nothing after midnight (e. g. nautic dawn, civil dawn), although event jobs get scheduled
(23:59:58.512 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home)
  • nothing fires at all after one day has elapsed with the system running.

I started OH2 in debug mode and also specifically log the binding:

log4j.logger.org.openhab.binding.astro = DEBUG, astro

As everything was working for months up until I switched to build 983 from 885 I assume the changed made to the scheduler broke the binding. Is there a way to get the last working version of the binding back?

I think I have the same problem.

I’m current on OH 2.2, build #988. I freshly installed the Astro binding when I was on build #986 (so with the new ESH version). And made all the settings.

I have the following rule:


rule "Zonsondergang - nachtverlichting aan"

when
    Channel 'astro:sun:local:set#event' triggered START 
then
	logInfo("Astro","De zon gaat onder. Slaapwel.")
        sendCommand(KNX_GV_Nachtverlichting_4_2_0, ON)
end

It does not get triggered.

At midnight I do see this:

2017-07-21 00:00:00.050 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:local
2017-07-21 00:00:00.282 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:local

If I check out the value of my Astro-items, the sun should have risen on 05:50 and will set at 21h37.

DateTime Astro_Sunrise_Starttime		"Zonsopgang [%1$tH:%1$tM]"  									<sunrise>			(gAstro)		{ channel="astro:sun:local:rise#start" }
DateTime Astro_Sunset_Starttime			"Zonsondergang [%1$tH:%1$tM]"  									<sunset>			(gAstro)		{ channel="astro:sun:local:set#start" }

I checked outside, the sun has actually risen. So I think the bug is in OpenHAB and not in the coding of the sun. :wink:

Sounds familiar. Did a fresh install of the system, build #988 yesterday as well (including moving all the zwave stuff :frowning: )
Started the system and all astro item initialized correctly.

16:12:04.507 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
16:12:04.514 [INFO ] [marthome.event.ItemStateChangedEvent] - Sunrise_Time changed from NULL to 2017-07-20T06:04:00.000-0500
16:12:04.517 [INFO ] [marthome.event.ItemStateChangedEvent] - Sunset_Time changed from NULL to 2017-07-20T19:53:00.000-0500
16:12:04.521 [INFO ] [marthome.event.ItemStateChangedEvent] - NauticDawn_Time changed from NULL to 2017-07-20T05:05:00.000-0500
16:12:04.524 [INFO ] [marthome.event.ItemStateChangedEvent] - CivilDawn_Time changed from NULL to 2017-07-20T05:38:00.000-0500
16:12:04.527 [INFO ] [marthome.event.ItemStateChangedEvent] - NauticDusk_Time changed from NULL to 2017-07-20T20:23:00.000-0500
16:12:04.529 [INFO ] [marthome.event.ItemStateChangedEvent] - CivilDusk_Time changed from NULL to 2017-07-20T19:56:00.000-0500

Then the channels fired yesterday evening as expected, i. e. civil dusk, nautical dusk:

19:55:59.613 [INFO ] [marthome.event.ChannelTriggeredEvent] - astro:sun:home:civilDusk#event triggered START
19:55:59.613 [INFO ] [marthome.event.ChannelTriggeredEvent] - astro:sun:home:set#event triggered END
20:22:59.568 [INFO ] [marthome.event.ChannelTriggeredEvent] - astro:sun:home:civilDusk#event triggered END
20:22:59.569 [INFO ] [marthome.event.ChannelTriggeredEvent] - astro:sun:home:nauticDusk#event triggered START

At midnight got the same scheduling message :

23:59:59.197 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home

Update: I tested the values of select items today (2017-07-21, 11:45), and here’s the result:

11:46:00.102 [INFO ] [eclipse.smarthome.model.script.event] - Civil dawn: CivilDawn_Time (Type=DateTimeItem, State=**2017-07-20**T05:38:00.000-0500, Label=Civil Dawn, Category=null)
11:46:00.103 [INFO ] [eclipse.smarthome.model.script.event] - Nautic dawn: NauticDawn_Time (Type=DateTimeItem, State=**2017-07-20**T05:05:00.000-0500, Label=Nautic Dawn, Category=null)

No wonder nothing happens after midnight.
So I guess once we have a change of date the scheduler doesn’t work correctly any more, which renders the binding useless for the time being.

Here the same problem.
Version 2.2.0-SNAPSHOT Build #988.

At midnight this message:

2017-07-21 23:59:59.982 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:22f155ed

At startup this message:

2017-07-22 09:00:43.800 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:22f155ed

After the job scheduling at 1 second before midnight on 2017-07-21:

23:59:59.652 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home

here’s the output of a rule scheduled for 1 minute after midnight:

00:01:00.009 [INFO ] [eclipse.smarthome.model.script.event] - Civil dawn: CivilDawn_Time (Type=DateTimeItem, State=2017-07-21T05:38:00.000-0500, Label=Civil Dawn, Category=null, Groups=[Astro])
00:01:00.010 [INFO ] [eclipse.smarthome.model.script.event] - Nautic dawn: NauticDawn_Time (Type=DateTimeItem, State=2017-07-21T05:06:00.000-0500, Label=Nautic Dawn, Category=null, Groups=[Astro])

So it seems that the scheduler indeed uses the current day (the one before midnight at the time of scheduling), and not the next day (2017-07-22).
That would at least explain why the dawn events do not fire at all.

This evening at 19:55 Civil Dawn should have fired and turned on the lights, as expected nothing happened.

Another update:

For one day the scheduler on midnight generated thiese messages:

23:59:57.426 [INFO ] [marthome.event.ItemStateChangedEvent] - NauticDusk_Time changed from 2017-07-21T20:22:00.000-0500 to 2017-07-22T20:22:00.000-0500
23:59:57.427 [INFO ] [marthome.event.ItemStateChangedEvent] - CivilDusk_Time changed from 2017-07-21T19:55:00.000-0500 to 2017-07-22T19:55:00.000-0500
00:00:00.015 [INFO ] [marthome.event.ItemStateChangedEvent] - Sunrise_Time changed from 2017-07-22T06:06:00.000-0500 to 2017-07-23T06:06:00.000-0500
00:00:00.016 [INFO ] [marthome.event.ItemStateChangedEvent] - Sunset_Time changed from 2017-07-22T19:52:00.000-0500 to 2017-07-23T19:52:00.000-0500
00:00:00.016 [INFO ] [marthome.event.ItemStateChangedEvent] - NauticDawn_Time changed from 2017-07-22T05:07:00.000-0500 to 2017-07-23T05:07:00.000-0500
00:00:00.017 [INFO ] [marthome.event.ItemStateChangedEvent] - CivilDawn_Time changed from 2017-07-22T05:39:00.000-0500 to 2017-07-23T05:39:00.000-0500
00:00:00.017 [INFO ] [marthome.event.ItemStateChangedEvent] - NauticDusk_Time changed from 2017-07-22T20:22:00.000-0500 to 2017-07-23T20:21:00.000-0500
00:00:00.017 [INFO ] [marthome.event.ItemStateChangedEvent] - CivilDusk_Time changed from 2017-07-22T19:55:00.000-0500 to 2017-07-23T19:54:00.000-0500

Note that the times for the new day are correct.
This led me to believe that there respective rules would finally be triggered - unfortunately, nothing happened again.
The following day midnight the job only logged the usual

23:59:57.421 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home

On my side it seems that the trigger is working for exactly 7 Days after that, the binding stop triggering. I install a new system on 04.07. first time it stops on 11.07.

I restart the system on 20.07. without any changes. and the trigger was working again to yesterday, it stops again. Today I restart again and will see if the trigger is working tomorrow…

Is there any solution? With this status the astro binding is useless!

My configuration and schedule you find here: Astro Binding: Event triggered Start bt no light switch on

Same for me.
It is stopping after some days. After restarting OH (2.1) it is fine for some days and is stopping to trigger the events again.
I do use mainly triggers with offsets to the normal sunset (-60 Min & +20 Min).

You are not alone:

so I guess it is time to create an issue from any of you in:

After 7 days I expirence the same issue again.

I can find a lot of the following error in the log file

2017-08-09 00:00:00.610 [ERROR] [thome.binding.astro.internal.job.Job] - Queue full
java.lang.IllegalStateException: Queue full
        at java.util.AbstractQueue.add(AbstractQueue.java:98)[:1.8.0_131]
        at org.eclipse.smarthome.binding.astro.handler.AstroThingHandler.addJobToQueue(AstroThingHandler.java:314)[410:org.eclipse.smarthome.binding.astro:0.9.0.b5]
        at org.eclipse.smarthome.binding.astro.internal.job.Job.schedule(Job.java:58)[410:org.eclipse.smarthome.binding.astro:0.9.0.b5]
        at org.eclipse.smarthome.binding.astro.internal.job.Job.scheduleEvent(Job.java:94)[410:org.eclipse.smarthome.binding.astro:0.9.0.b5]
        at org.eclipse.smarthome.binding.astro.internal.job.Job.scheduleRange(Job.java:114)[410:org.eclipse.smarthome.binding.astro:0.9.0.b5]
        at org.eclipse.smarthome.binding.astro.internal.job.DailyJobSun.run(DailyJobSun.java:64)[410:org.eclipse.smarthome.binding.astro:0.9.0.b5]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_131]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_131]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
        at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]

Actually the “Queue full” error was fixed more than four weeks ago, are you sure you are running a recent astro binding ?
(and maybe also a recent 2.2 snapshot runtime is needed):

I think different type issues are discussed in this thread. In my post, I didn’t mention the Queue full error message. It is just that the Channel ‘astro:sun:local:set#event’ does not get triggered.

I have created an issue for this:

If others have the same problem, feel free to add additional information. I wasn’t sure what other information could be relevant.

Thanks a lot for your answer.

Oh. I was not aware. As mentioned before, I am using the stable release 2.1.
Good to know that this bug was fixed, but as this bug was fixed after the stable release, people like me who try to use stable (suggest more tested and reliable) releases for their production environment, this is not perfect :joy:

I will try to use the latest binding from 2.2 and see if this helps.

The issue has been solved. See also my post in this topic.

1 Like

I have the same issue and can now re-produce it.
I’m using OH 2.2.0-SNAPSHOT Build #1020.

Everything works fine until I do a reboot of the system. Could be, that the same behavior can be seen after restarting the service. The schedule for the current day is fine but at midnight the schedule job for astro:sun:local thing is not triggered. You can see this in the log file as well. Only “moon” is logged.

After clearing all things, links and items in the console, re-start of OH2.2 and manually adding the things moon and sun in the paper UI, it’s working correct again.

Hope that helps to find the issue.

You are using an old build. The issue has been fixed a while ago, you should upgrade to a recent build.

1 Like

I updated now to Build #1039. I will check tomorrow :smiley:

1 Like

Cool. Works like a charm now :heart_eyes:

1 Like

Any ideas when this fix will be part pf stable release? If taking weeks, then it would be worth of upgrading to Snapshot, IMHO.

I think you are asking when OpenHAB 2.2 will be released. I don’t think that this has been decided (or made public). It could be days, weeks or even months.

If you don’t like that uncertainty, you can indeed switch to the snapshots (despite the fact they are snapshots, I can’t say they are less stable). Alternatively, read this post. You could add the newer Astro-JAR to your current OpenHAB 2.1 installation.