Astro binding does not trigger: has no future executions anymore

With the latest snapshot from this morning #961 the astro binding does not trigger events anmyore:

openhab.log (one example from many):

2017-06-22 21:57:00.393 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 57 21 22 6 ? 2017' has no future executions anymore

During startup I’m seeing (restart does not solve the problem):

2017-06-22 15:03:10.439 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/config/config.xml' in module 'org.eclipse.smarthome.binding.astro' could not be parsed: lat : lat
---- Debugging information ----
message             : lat
cause-exception     : com.thoughtworks.xstream.mapper.CannotResolveClassException
cause-message       : lat
class               : java.util.ArrayList
required-type       : java.util.ArrayList
converter-type      : com.thoughtworks.xstream.converters.collections.CollectionConverter
path                : /config-descriptions/config-description/parameter/description/lat
line number         : 11
class[1]            : org.eclipse.smarthome.config.core.ConfigDescriptionParameter
converter-type[1]   : org.eclipse.smarthome.config.xml.ConfigDescriptionParameterConverter
class[2]            : org.eclipse.smarthome.config.core.ConfigDescription
converter-type[2]   : org.eclipse.smarthome.config.xml.ConfigDescriptionConverter
version             : 1.4.7
-------------------------------
com.thoughtworks.xstream.converters.ConversionException: lat : lat
---- Debugging information ----
message             : lat
cause-exception     : com.thoughtworks.xstream.mapper.CannotResolveClassException
cause-message       : lat
class               : java.util.ArrayList
required-type       : java.util.ArrayList
converter-type      : com.thoughtworks.xstream.converters.collections.CollectionConverter
path                : /config-descriptions/config-description/parameter/description/lat
line number         : 11
class[1]            : org.eclipse.smarthome.config.core.ConfigDescriptionParameter
converter-type[1]   : org.eclipse.smarthome.config.xml.ConfigDescriptionParameterConverter
class[2]            : org.eclipse.smarthome.config.core.ConfigDescription
converter-type[2]   : org.eclipse.smarthome.config.xml.ConfigDescriptionConverter
version             : 1.4.7
-------------------------------
	at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:79)[98:org.eclipse.smarthome.config.xml:0.9.0.201706211154]
	at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65)[98:org.eclipse.smarthome.config.xml:0.9.0.201706211154] ...

Astro things and channels are GUI configured.

Edit: did the syntax for lat/lon change? Adding a new thing shows:

2017-06-22 23:04:58.149 [ERROR] [ding.astro.handler.AstroThingHandler] - Astro parameter geolocation is mandatory and must be configured, disabling thing 'astro:sun:d8d1e9c3'
2017-06-22 23:04:58.151 [ERROR] [ding.astro.handler.AstroThingHandler] - Astro parameters geolocation could not be split into latitude and longitude, disabling thing 'astro:sun:d8d1e9c3'
2017-06-22 23:04:58.153 [ERROR] [ding.astro.handler.AstroThingHandler] - Astro parameter interval must be in the range of 1-86400, disabling thing 'astro:sun:d8d1e9c3'

regardless if I use a comma between lat/lon or a colon …

Issue created:

1 Like

I see the same on S#963

root@homer:/var/log/openhab2# tail openhab.log 
2017-06-23 05:32:00.010 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 32 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:32:00.010 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 32 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:32:00.012 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 32 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:32:00.012 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 32 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:36:00.010 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 36 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:36:00.011 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 36 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:36:00.011 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 36 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:36:00.012 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 36 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:36:00.014 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 36 5 23 6 ? 2017' has no future executions anymore
2017-06-23 05:36:00.015 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 36 5 23 6 ? 2017' has no future executions anymore

edit: I don’t have any errors for the Astro binding in my log (but I didn’t try to add a new Thing with it to replicate the issue)

openhab> list -s |grep -i astro
191 | Active   |  80 | 0.9.0.201706211517     | Astro Binding    | org.eclipse.smarthome.binding.astro

Issue was closed because it already got fixed. Now waiting for the fix to make it into the snapshot … or reverting to an older installation.

1 Like

No need to wait - it is included since yesterday already.

1 Like

I see the same errors in the stable build from yesterday - do i have to recreate things or something?

2017-06-30 04:37:00.004 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 37 4 30 6 ? 2017' has no future executions anymore
2017-06-30 04:37:00.004 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 37 4 30 6 ? 2017' has no future executions anymore
2017-06-30 04:37:00.004 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 37 4 30 6 ? 2017' has no future executions anymore
2017-06-30 05:18:00.003 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 18 5 30 6 ? 2017' has no future executions anymore
2017-06-30 05:18:00.003 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 18 5 30 6 ? 2017' has no future executions anymore
2017-06-30 05:18:00.004 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 18 5 30 6 ? 2017' has no future executions anymore
2017-06-30 05:22:00.003 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 22 5 30 6 ? 2017' has no future executions anymore
2017-06-30 05:22:00.003 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 22 5 30 6 ? 2017' has no future executions anymore
2017-06-30 05:22:00.004 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 22 5 30 6 ? 2017' has no future executions anymore


Line 20823: 2017-06-30 04:37:00.002 [ChannelTriggeredEvent     ] - astro:sun:local:nauticDawn#event triggered END
Line 20824: 2017-06-30 04:37:00.020 [ChannelTriggeredEvent     ] - astro:sun:local:civilDawn#event triggered START
Line 21378: 2017-06-30 05:18:00.004 [ChannelTriggeredEvent     ] - astro:sun:local:civilDawn#event triggered END
Line 21379: 2017-06-30 05:18:00.005 [ChannelTriggeredEvent     ] - astro:sun:local:rise#event triggered START
Line 21446: 2017-06-30 05:22:00.003 [ChannelTriggeredEvent     ] - astro:sun:local:rise#event triggered END
Line 21447: 2017-06-30 05:22:00.010 [ChannelTriggeredEvent     ] - astro:sun:local:daylight#event triggered START

I see the same errors in my log but my local_sun set and ride events are still triggering.

yeah, seems like the triggering is still working… i recreated the sun :joy: to see if that changes something!

I’m only seeing INFO labels, no ERROR labels :grin:

But those messages could better be raised to DEBUG level …

man you are right, that’s the third time i’m falling over the same stone… i think i’ll edit my log level - shame on me!

Actually a better idea is to open an issue so those astro messages go into debug level log instead of info level log.
If you would raise your message log to WARN or even higher you may miss some needed messages …

1 Like

first of all i recreated things to make sure this isn’t an interaction with the update to 2.1 - if theese messages persist, i will create that issue.

thanks!

It’s not :grinning:

Great :fu:

i hope everything is in the right place, i never created an issue on github…

1 Like

Almost: because the astro binding is part of Eclipse it should have gone to:

But I’m sure you will get a message if it needs to be moved, so don’t worry.
And: it is always a good idea to link to a forum thread (like this one) to have a a reference and additional information for the maintainers.

Thanks for the hints, i inserted the topic there.

2 Likes

Fixed with

https://github.com/eclipse/smarthome/pull/3751

3 Likes

Thanks! If i don’t want to change the binding yet, only the loglevel, i tried to do it in the karaf konsole with:

log:set WARN org.eclipse.smarthome.binding.astro

the result is:

openhab> log:list
Logger                                                      | Level
-------------------------------------------------------------------
ROOT                                                        | WARN
javax.jmdns                                                 | ERROR
org.apache.aries.spifly                                     | ERROR
org.apache.karaf.kar.internal.KarServiceImpl                | ERROR
org.eclipse.smarthome                                       | INFO
org.eclipse.smarthome.binding.astro                         | WARN
org.jupnp                                                   | ERROR
org.openhab                                                 | INFO
org.openhab.binding.mysensors                               | ERROR
org.openhab.binding.zwave                                   | WARN
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper | ERROR
smarthome.event                                             | INFO
smarthome.event.InboxUpdatedEvent                           | ERROR
smarthome.event.ItemAddedEvent                              | ERROR
smarthome.event.ItemRemovedEvent                            | ERROR
smarthome.event.ItemStateEvent                              | ERROR
smarthome.event.ThingStatusInfoEvent                        | ERROR

but this morning i still got theese info entrys in my log file.

2017-07-01 05:22:00.013 [INFO ] [Manager$ExpressionThreadPoolExecutor] - Expression '0 22 5 1 7 ? 2017' has no future executions anymore

What am i messing up? Thanks!

I think that the INFO log entry is originating from org.eclipse.smarthome.core.scheduler (where Christoph applied the fix also)
try to lower the log level for that

Hmm, today my sun rise event didn’t trigger, I didn’t see anything interesting in the logs though. I’ll see if set triggers this evening.

I haven’t upgraded to 2.1 yet though, I’m still on build 964.