Smarthome: astro binding missing events
I am using the following openhab2 SNAPSHOT:
Package: openhab2
Versions:
2.1.0~20170623003852-1 (/var/lib/apt/lists/openhab.jfrog.io_openhab_openhab-linuxpkg_dists_unstable_main_binary-armhf_Packages)
Description Language:
File: /var/lib/apt/lists/openhab.jfrog.io_openhab_openhab-linuxpkg_dists_unstable_main_binary-armhf_Packages
MD5: 326ece3868ef747762229ee66dc0da02
openhab> bundle:list | grep -i astro
177 | Active | 80 | 0.9.0.201706211517 | Astro Binding
openhab> feature:list | grep -i astro
openhab-binding-astro1 | 1.10.0.SNAPSHOT | | Uninstalled | openhab-addons-legacy-2.1.0-SNAPSHOT | Astro Binding (1.x)
esh-binding-astro | 0.9.0.SNAPSHOT | | Started | addons-2.1.0-SNAPSHOT |
openhab-binding-astro | 2.1.0.SNAPSHOT | x | Started | addons-2.1.0-SNAPSHOT | Astro Binding
Sometimes my rules, based on astro events, are not fired. As I look into my events.log I am missing some events of the astro binding. Examples (These are ALL events of my astro:sun:rolladen Thing in the events log in that time:
2017-06-21 22:21:00.036 [ChannelTriggeredEvent ] - astro:sun:rolladen:set#event triggered START
2017-06-21 22:25:00.023 [ChannelTriggeredEvent ] - astro:sun:rolladen:set#event triggered END
2017-06-21 22:44:00.042 [ChannelTriggeredEvent ] - astro:sun:rolladen:civilDusk#event triggered END
2017-06-22 08:00:00.047 [ChannelTriggeredEvent ] - astro:sun:rolladen:rise#event triggered END
2017-06-22 22:26:00.044 [ChannelTriggeredEvent ] - astro:sun:rolladen:set#event triggered END
2017-06-22 22:44:00.054 [ChannelTriggeredEvent ] - astro:sun:rolladen:civilDusk#event triggered END
2017-06-23 08:00:00.037 [ChannelTriggeredEvent ] - astro:sun:rolladen:rise#event triggered START
As you can see, sometimes the START events are missing, sometimes the END events are missing.
What could be causing this?
Thanks and greets
dvehof
All 27 comments
I can confirm that astro triggers are not working anymore, snapshot 964.
Astro thing astro:sun:shutterkitchen created through PaperUI, geolocation northwestern part of Germany, offset=0, latest=20:45, refresh interval 3600, trigger channel Channel 'astro:sun:shutterkitchen:set#event' triggered END , debug log shows:
2017-06-23 20:45:00.539 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:wss3
2017-06-23 20:45:00.768 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 45 20 23 6 ? 2017' has no future executions anymore
2017-06-23 20:45:00.843 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 45 20 23 6 ? 2017' has no future executions anymore
2017-06-23 20:50:00.538 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:wss3
So there is only an indication (refresh) from one of my other astro things astro:sun:wss3
events.log: no entry for 20:45, only one entry for today for astro:sun:shutterkitchen:
2017-06-23 13:33:00.903 [ChannelTriggeredEvent ] - astro:sun:shutterkitchen:noon#event triggered START
sihui62
on 23 Jun 2017
@amitjoy & @triller-telekom This sounds like a critical regression to me, could you please check?
kaikreuzer
on 24 Jun 2017
I roughly looked at it. I have set custom date for Sunrise and the logs are a bit weird.
09:26:54.009 INFO s.event.ChannelTriggeredEvent[:43] - astro:sun:local:rise#event triggered START
09:26:54.010 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.011 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.012 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.012 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.013 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.013 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.013 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.013 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.014 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.014 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.014 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.015 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
09:26:54.015 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
It still fires the event but ExpressionThreadPoolManager keeps on saying that the scheduled time has no future. I looked at the source of this log and it appears if the cron expression denotes a time that is not a future time.
amitjoy
on 24 Jun 2017
@amitjoy Thanks for looking into it!
@kgoderis Might there be an issue with the scheduler service? These logs indeed look a bit weird...
kaikreuzer
on 24 Jun 2017
Even the END event gets triggered as well.
09:35:06.012 INFO s.event.ChannelTriggeredEvent[:43] - astro:sun:local:rise#event triggered END
09:35:06.013 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.014 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.015 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.015 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.015 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.016 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.016 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.016 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.016 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.017 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.017 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.019 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
09:35:06.020 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '6 35 9 24 6 ? 2017' has no future executions anymore
And the strange thing is that if the event has no future executions anymore, then how could the event be fired at the first place? I will try my best to find if there is anything interesting going on.
amitjoy
on 24 Jun 2017
@amitjoy I assume we need a fix for this as well, dont we?
tomhoefer
on 24 Jun 2017
@tomhoefer I have tried to trigger custom sunrise events and the START and END events are fired at the specified times. In addition, there are some scheduler-related logs that are a bit strange to me. I have enclosed the logs in this thread as well. I have debugged astro-binding's DailySunJob that triggers range events but I couldn't find any potential issue. I might be missing something. I will have another look again. As astro-binding is tightly dependent on ESH Scheduler, there might be some issue in ExpressionThreadPoolExecutor as well. We need to investigate that accordingly.
amitjoy
on 24 Jun 2017
@kgoderis Might there be an issue with the scheduler service? These logs indeed look a bit weird...
Mhhh... to me they look OK, that is if you consider
09:26:54.010 INFO o.e.s.c.s.ExpressionThreadPoolManager$ExpressionThreadPoolExecutor[:225] - Expression '54 26 9 24 6 ? 2017' has no future executions anymore
then in theory the expression should not trigger anymore after 09:26:54.000 . It is thus 10 ms too late, but I suspect that we have somewhere a comparison problem in the code where the system time at time of comparison is a few ms past the trigger timestamp, or I guess the astro code tries to schedule an expression (since the CronExpression seem to define a timestamp to the second precisely), but that this scheduling itself takes a few ms, making the expression not trigger anymore. Need to delve into the code I guess
kgoderis
on 24 Jun 2017
@kaikreuzer @amitjoy @triller-telekom
It seems a CronExpression is created based on some event data, with precise timing information, and then scheduled for (immediate) execution a few lines later (and thus a few ms later), no?
kgoderis
on 24 Jun 2017
@kgoderis [1] creates a cron expression out of an expected future time when some event is scheduled to be fired. The cron expression explicitly specifies the seconds, hours, minutes and the rest to schedule a specific event. I am not sure if CronExpression class also considers the milliseconds to schedule an event. My idea was to execute the scheduled event as soon as the exact time ticks without considering the explicit milliseconds as generally in cron expressions, milliseconds are ignored.
amitjoy
on 24 Jun 2017
I am not sure if CronExpression class also considers the milliseconds to schedule an event
ah.... AFAIRemember I did some rounding whilst crafting the CronExpression class, as milliseconds are not specified in the Quartz definition anyways. Maybe you can try to schedule the expression to first second in the future?
kgoderis
on 24 Jun 2017
I could try to schedule it to the first second in the future. Currently astro binding creates all schedules based on future date - for example, 0 59 19 24 6 ? 2017 and astro binding expects to have the scheduled event triggered at 07:59 PM, on day 24 of the month, only in June, only in 2017. And sometimes the events get triggered and sometimes not with the message - Expression 'X' has no future executions anymore.
amitjoy
on 24 Jun 2017
@amitjoy : Is there anything I can do to help you? Further Information needed or should l test something?
dvehof
on 26 Jun 2017
@dvehof & @sihui62 I will provide a new distro build later this evening that will contain the fix (I'll ping you as soon as it is available) - it would be awesome if you could install it and let it run tonight and report your findings after sunrise tomorrow :-)
kaikreuzer
on 26 Jun 2017
it would be awesome if you could install it and let it run tonight
No problem, readily available for testing
sihui62
on 26 Jun 2017
@dvehof As @kaikreuzer said, we have probably fixed this issue. It would be really helpful if you can test it in your current environment and let us know if it works.
amitjoy
on 26 Jun 2017
@dvehof & @sihui62 Here you go: https://openhab.ci.cloudbees.com/job/openHAB-Distribution/970/
Please test and report back - thanks!
kaikreuzer
on 26 Jun 2017
@amitjoy @kaikreuzer : Thanks for your great work and help, for sure I will install it and report back if it works!
dvehof
on 26 Jun 2017
New build 970 is up and running, first of my regular triggers was already fired successfully ;-). In addition to the regular triggers I have set up some test triggers, will provide the results tomorrow.
```
2017-06-26 20:45:07.661 [ChannelTriggeredEvent ] - astro:sun:shutterkitchen:set#event triggered END
2017-06-26 20:45:07.662 [ChannelTriggeredEvent ] - astro:sun:shutterkitchen:set#event triggered START
...
2017-06-26 20:45:00.173 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:wss3
2017-06-26 20:45:00.322 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 45 20 26 6 ? 2017' has no future executions anymore
2017-06-26 20:45:00.361 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 45 20 26 6 ? 2017' has no future executions anymore
sihui62
on 26 Jun 2017
Also installed latest build, for now all events seem to trigger fine:
...
2017-06-26 21:51:00.009 [ChannelTriggeredEvent ] - astro:sun:home:set#event triggered START
2017-06-26 21:51:00.010 [ChannelTriggeredEvent ] - astro:sun:rolladen:daylight#event triggered END
2017-06-26 21:51:00.014 [ChannelTriggeredEvent ] - astro:sun:home:daylight#event triggered END
2017-06-26 21:56:00.014 [ChannelTriggeredEvent ] - astro:sun:home:civilDusk#event triggered START
2017-06-26 21:56:00.039 [ChannelTriggeredEvent ] - astro:sun:home:set#event triggered END
2017-06-26 21:56:00.059 [ChannelTriggeredEvent ] - astro:sun:rolladen:civilDusk#event triggered START
2017-06-26 22:21:00.008 [ChannelTriggeredEvent ] - astro:sun:rolladen:set#event triggered START
2017-06-26 22:26:00.046 [ChannelTriggeredEvent ] - astro:sun:rolladen:set#event triggered END
...
Will check again tomorrow!
dvehof
on 26 Jun 2017
I can confirm the astro binding is working fine again.
All my regular events were fired at the correct times, all test events with a couple of offsets and earliest/latest were fired at the correct times.
Thx a lot for this great and fast support!
sihui62
on 27 Jun 2017
This morning:
2017-06-26 22:44:00.005 [ChannelTriggeredEvent ] - astro:sun:rolladen:nauticDusk#event triggered START
2017-06-26 22:44:00.009 [ChannelTriggeredEvent ] - astro:sun:rolladen:civilDusk#event triggered END
2017-06-26 22:44:00.023 [ChannelTriggeredEvent ] - astro:sun:home:civilDusk#event triggered END
2017-06-26 22:44:00.040 [ChannelTriggeredEvent ] - astro:sun:home:nauticDusk#event triggered START
2017-06-26 23:37:00.016 [ChannelTriggeredEvent ] - astro:moon:home:set#event triggered END
2017-06-27 03:07:00.015 [ChannelTriggeredEvent ] - astro:sun:home:astroDawn#event triggered END
2017-06-27 03:07:00.018 [ChannelTriggeredEvent ] - astro:sun:rolladen:nauticDawn#event triggered START
2017-06-27 03:07:00.030 [ChannelTriggeredEvent ] - astro:sun:home:nauticDawn#event triggered START
2017-06-27 03:07:00.102 [ChannelTriggeredEvent ] - astro:sun:rolladen:astroDawn#event triggered END
2017-06-27 04:25:00.010 [ChannelTriggeredEvent ] - astro:sun:rolladen:nauticDawn#event triggered END
2017-06-27 04:25:00.022 [ChannelTriggeredEvent ] - astro:sun:home:nauticDawn#event triggered END
2017-06-27 04:25:00.057 [ChannelTriggeredEvent ] - astro:sun:home:civilDawn#event triggered START
2017-06-27 04:25:00.079 [ChannelTriggeredEvent ] - astro:sun:rolladen:civilDawn#event triggered START
2017-06-27 05:14:00.040 [ChannelTriggeredEvent ] - astro:sun:home:civilDawn#event triggered END
2017-06-27 05:14:00.101 [ChannelTriggeredEvent ] - astro:sun:home:rise#event triggered START
2017-06-27 05:14:00.121 [ChannelTriggeredEvent ] - astro:sun:rolladen:civilDawn#event triggered END
2017-06-27 05:18:00.004 [ChannelTriggeredEvent ] - astro:sun:rolladen:daylight#event triggered START
2017-06-27 05:18:00.078 [ChannelTriggeredEvent ] - astro:sun:home:daylight#event triggered START
2017-06-27 05:18:00.122 [ChannelTriggeredEvent ] - astro:sun:home:rise#event triggered END
2017-06-27 08:00:00.004 [ChannelTriggeredEvent ] - astro:sun:rolladen:rise#event triggered END
2017-06-27 08:00:00.026 [ChannelTriggeredEvent ] - astro:sun:rolladen:rise#event triggered START
2017-06-27 09:22:00.025 [ChannelTriggeredEvent ] - astro:moon:home:rise#event triggered START
Seems to be working correctly!
One thing I saw:
2017-06-27 08:00:00.004 [ChannelTriggeredEvent ] - astro:sun:rolladen:rise#event triggered END
2017-06-27 08:00:00.026 [ChannelTriggeredEvent ] - astro:sun:rolladen:rise#event triggered START
The END event is triggered before the start event (mybe just a logging delay?). The event is moved by "earliest/latest" setting, mabye that is causing this, they should both fire at 8:00, so this is not a problem, just to let you know.
Thanks again for fixing this, you guys are awesome!
dvehof
on 27 Jun 2017
mybe just a logging delay?
I guess that is the case. Without any offset or earliest/latest it shows:
2017-06-27 05:46:00.365 [ChannelTriggeredEvent ] - astro:sun:test:rise#event triggered START
2017-06-27 05:51:00.074 [ChannelTriggeredEvent ] - astro:sun:test:rise#event triggered END
mybe just a logging delay?
might indeed be the case. On the other hand, the scheduler just works on granularity of seconds, so it tries to schedule those two events for the identical time. And as these are independently scheduled events, we also get some fuzziness which naturally comes with multi threaded/parallel execution. Therefore it might not only be the logging, it actually also could be just coincidence.
Therefore I suggest to further improve the astro binding to add a delay of at least one second to the end events in case start and end are to be scheduled "at the same time". I suppose such a small delay hurts us much less than the consequences in rules when the order is screwed up.
sjsf
on 27 Jun 2017
Therefore I suggest to further improve the astro binding to add a delay of at least one second to the end events in case start and end are to be scheduled "at the same time". I suppose such a small delay hurts us much less than the consequences in rules when the order is screwed up.
Just commenting on a closed issue (@sjka) because with build 988 there seems to be still the problem with:
The END event is triggered before the start event (mybe just a logging delay?). The event is moved by "earliest/latest" setting, mabye that is causing this, they should both fire at 8:00, so this is not a problem, just to let you know.
2017-07-23 08:30:15.468 [ChannelTriggeredEvent ] - astro:sun:shutterkitchen:civilDawn#event triggered END
2017-07-23 08:30:15.475 [ChannelTriggeredEvent ] - astro:sun:shutterkitchen:civilDawn#event triggered START
2017-07-23 08:45:11.980 [ChannelTriggeredEvent ] - astro:sun:shutterlivingroom:civilDawn#event triggered END
2017-07-23 08:45:11.997 [ChannelTriggeredEvent ] - astro:sun:shutterlivingroom:civilDawn#event triggered START
Both events are triggered with an "earliest" offset, but they do work as expected. There are no mismatches in START/END order for triggers without any offsets.
sihui62
on 23 Jul 2017
That's weird...
What is the exact bundle version of your astro binding (e.g. from bundle:list)?
sjsf
on 24 Jul 2017
Ah, sorry, it took a while for your last sentence to sink in...
You indeed discovered a bug in the control flow when the earliest/latest configuration leads to the events to be fired at the same time. I have opened #3882 to track it.
sjsf
on 24 Jul 2017
Related issues
afuechsel
路
9Comments
doandzhi
路
6Comments
Josar
路
7Comments
sjsf
路
7Comments
kubawolanin
路
3Comments
Most helpful comment
might indeed be the case. On the other hand, the scheduler just works on granularity of seconds, so it tries to schedule those two events for the identical time. And as these are independently scheduled events, we also get some fuzziness which naturally comes with multi threaded/parallel execution. Therefore it might not only be the logging, it actually also could be just coincidence.
Therefore I suggest to further improve the astro binding to add a delay of at least one second to the end events in case start and end are to be scheduled "at the same time". I suppose such a small delay hurts us much less than the consequences in rules when the order is screwed up.