openhab-addons icon indicating copy to clipboard operation
openhab-addons copied to clipboard

Published 20 hours ago • verified publisher icon openhab

[astro] rules/events not triggering after Upgrade to 3.2M1

Open openPhiL opened this issue 3 years ago • 10 comments

Hi. I upgraded from 3.1M3 to 3.2M1 yesterday and realize, that astro is not working. Just not triggering the simple rule I have (which was working like forever).

Rule: 
triggers:
  - id: "3"
    configuration:
      thingUID: astro:sun:local
      event: START
      channelUID: astro:sun:local:daylight#event
    type: core.ChannelEventTrigger
conditions: []
actions:
  - inputs: {}
    id: "1"
    configuration:
      itemName: Tageslicht
      command: ON
    type: core.ItemCommandAction

So I tried uninstalling the binding before reinstalling it, and found those log errors, that might explain something to the developer-eye? Or would you help me setting up the log-settings so that the log is more helpful to you?

==> /var/log/openhab/events.log <==

2021-08-08 22:19:18.240 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:moon:local' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)

2021-08-08 22:19:18.242 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from ONLINE to UNINITIALIZED

==> /var/log/openhab/openhab.log <==

2021-08-08 22:19:18.249 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 17 MultipleDynamic removed {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton} (enter)

2021-08-08 22:19:18.249 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : invoking unbind: removeThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:18.250 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - Thing automation action removed => rules are going to be refreshed

2021-08-08 22:19:18.250 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : invoked unbind: removeThingActions

2021-08-08 22:19:18.250 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 17 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton}

2021-08-08 22:19:18.251 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 13 MultipleDynamic removed {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton} (enter)

2021-08-08 22:19:18.252 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : invoking unbind: removeThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:18.252 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : invoked unbind: removeThingActions

2021-08-08 22:19:18.252 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 13 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton}

2021-08-08 22:19:18.252 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 18 MultipleDynamic removed {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton} (enter)

2021-08-08 22:19:18.254 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : invoking unbind: removeThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:18.261 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : invoked unbind: removeThingActions

2021-08-08 22:19:18.262 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 18 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton}

2021-08-08 22:19:18.265 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 7 MultipleDynamic removed {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton} (enter)

2021-08-08 22:19:18.266 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : invoking unbind: removeThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:18.266 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : invoked unbind: removeThingActions

2021-08-08 22:19:18.268 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 7 MultipleDynamic removed (unbind) {org.openhab.core.thing.binding.ThingActions}={service.id=592, service.bundleid=262, service.scope=singleton}

==> /var/log/openhab/events.log <==

2021-08-08 22:19:18.269 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)

==> /var/log/openhab/openhab.log <==

2021-08-08 22:19:18.320 [INFO ] [internal.service.FeaturesServiceImpl] - Uninstalling bundles:

2021-08-08 22:19:18.321 [INFO ] [internal.service.FeaturesServiceImpl] -   org.openhab.binding.astro/3.2.0.M1

2021-08-08 22:19:18.382 [INFO ] [internal.service.FeaturesServiceImpl] - Refreshing bundles:

2021-08-08 22:19:18.425 [INFO ] [internal.service.FeaturesServiceImpl] -     org.openhab.binding.astro/3.2.0.M1 (Bundle will be uninstalled)

2021-08-08 22:19:18.448 [INFO ] [internal.service.FeaturesServiceImpl] - Done.

2021-08-08 22:19:33.309 [INFO ] [internal.service.FeaturesServiceImpl] - Adding features: openhab-binding-astro/[3.2.0.M1,3.2.0.M1]

2021-08-08 22:19:39.666 [INFO ] [internal.service.FeaturesServiceImpl] - Changes to perform:

2021-08-08 22:19:39.668 [INFO ] [internal.service.FeaturesServiceImpl] -   Region: root

2021-08-08 22:19:39.668 [INFO ] [internal.service.FeaturesServiceImpl] -     Bundles to install:

2021-08-08 22:19:39.668 [INFO ] [internal.service.FeaturesServiceImpl] -       mvn:org.openhab.addons.bundles/org.openhab.binding.astro/3.2.0.M1

2021-08-08 22:19:39.676 [INFO ] [internal.service.FeaturesServiceImpl] - Installing bundles:

2021-08-08 22:19:39.677 [INFO ] [internal.service.FeaturesServiceImpl] -   mvn:org.openhab.addons.bundles/org.openhab.binding.astro/3.2.0.M1

2021-08-08 22:19:39.811 [INFO ] [internal.service.FeaturesServiceImpl] - Starting bundles:

2021-08-08 22:19:39.813 [INFO ] [internal.service.FeaturesServiceImpl] -   org.openhab.binding.astro/3.2.0.M1

2021-08-08 22:19:39.913 [INFO ] [internal.service.FeaturesServiceImpl] - Done.

2021-08-08 22:19:39.984 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 18 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:39.996 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 18 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:39.996 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:39.997 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - Thing automation action added => rules are going to be refreshed

2021-08-08 22:19:39.997 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : invoked bind: addThingActions

2021-08-08 22:19:39.997 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 18 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (exit)

2021-08-08 22:19:39.998 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 14 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:39.998 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 14 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:39.998 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:39.998 [DEBUG] [e.model.rule.scoping.RulesClassCache] - Updated cache entry: org.openhab.binding.astro.internal.action.AstroActions

2021-08-08 22:19:39.999 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : invoked bind: addThingActions

2021-08-08 22:19:39.999 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 14 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (exit)

2021-08-08 22:19:39.999 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 19 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:40.000 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 19 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:40.008 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:40.009 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : invoked bind: addThingActions

2021-08-08 22:19:40.009 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 19 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (exit)

2021-08-08 22:19:40.010 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 8 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:40.010 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 8 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:40.010 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:40.010 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : invoked bind: addThingActions

2021-08-08 22:19:40.011 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 8 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=664, service.bundleid=295, service.scope=singleton} (exit)

==> /var/log/openhab/events.log <==

2021-08-08 22:19:40.036 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:moon:local' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING

2021-08-08 22:19:40.042 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:moon:local' changed from INITIALIZING to ONLINE

==> /var/log/openhab/openhab.log <==

2021-08-08 22:19:40.092 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 19 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:40.093 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 19 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:40.093 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:40.094 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - Thing automation action added => rules are going to be refreshed

2021-08-08 22:19:40.094 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : invoked bind: addThingActions

2021-08-08 22:19:40.094 [DEBUG] [e.model.rule.jvmmodel.RulesRefresher] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.jvmmodel.RulesRefresher(197)] : dm ThingActions tracking 19 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (exit)

2021-08-08 22:19:40.095 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 15 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:40.095 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 15 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:40.095 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:40.095 [DEBUG] [e.model.rule.scoping.RulesClassCache] - Updated cache entry: org.openhab.binding.astro.internal.action.AstroActions

2021-08-08 22:19:40.096 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : invoked bind: addThingActions

2021-08-08 22:19:40.096 [DEBUG] [e.model.rule.scoping.RulesClassCache] - bundle org.openhab.core.model.rule:3.2.0.M1 (198)[org.openhab.core.model.rule.scoping.RulesClassCache(198)] : dm ThingActions tracking 15 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (exit)

2021-08-08 22:19:40.105 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 20 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:40.106 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 20 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:40.106 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:40.106 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : invoked bind: addThingActions

2021-08-08 22:19:40.107 [DEBUG] [.core.model.script.ScriptServiceUtil] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.ScriptServiceUtil(201)] : dm ThingActions tracking 20 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (exit)

2021-08-08 22:19:40.107 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 9 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (enter)

2021-08-08 22:19:40.107 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 9 MultipleDynamic already active, binding {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton}

2021-08-08 22:19:40.108 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : invoking bind: addThingActions: parameters [org.openhab.binding.astro.internal.action.AstroActions]

2021-08-08 22:19:40.108 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : invoked bind: addThingActions

2021-08-08 22:19:40.108 [DEBUG] [nal.engine.action.ThingActionService] - bundle org.openhab.core.model.script:3.2.0.M1 (201)[org.openhab.core.model.script.internal.engine.action.ThingActionService(208)] : dm ThingActions tracking 9 MultipleDynamic added {org.openhab.core.thing.binding.ThingActions}={service.id=665, service.bundleid=295, service.scope=singleton} (exit)

==> /var/log/openhab/events.log <==

2021-08-08 22:19:40.133 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING

2021-08-08 22:19:40.141 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'astro:sun:local' changed from INITIALIZING to ONLINE

==> /var/log/openhab/openhab.log <==

2021-08-08 22:19:40.170 [ERROR] [enhab.binding.astro.internal.job.Job] - Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@35c403[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@a49c7b[Wrapped task = Event job astro:sun:local/night#event/START]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@35c403[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@a49c7b[Wrapped task = Event job astro:sun:local/night#event/START]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Unknown Source) ~[?:?]

	at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(Unknown Source) ~[?:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.schedule(AstroThingHandler.java:307) ~[bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.schedule(Job.java:60) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleEvent(Job.java:109) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleEvent(Job.java:78) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleRange(Job.java:141) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.DailyJobSun.run(DailyJobSun.java:66) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.restartJobs(AstroThingHandler.java:203) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.initialize(AstroThingHandler.java:126) [bundleFile:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]

	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]

	at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]

	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]

	at java.lang.Thread.run(Unknown Source) [?:?]

2021-08-08 22:19:40.175 [ERROR] [enhab.binding.astro.internal.job.Job] - Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@1b31206[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1a2ca6d[Wrapped task = Event job astro:sun:local/astroDusk#event/END]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@1b31206[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1a2ca6d[Wrapped task = Event job astro:sun:local/astroDusk#event/END]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Unknown Source) ~[?:?]

	at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(Unknown Source) ~[?:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.schedule(AstroThingHandler.java:307) ~[bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.schedule(Job.java:60) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleEvent(Job.java:109) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleEvent(Job.java:78) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleRange(Job.java:142) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.DailyJobSun.run(DailyJobSun.java:71) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.restartJobs(AstroThingHandler.java:203) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.initialize(AstroThingHandler.java:126) [bundleFile:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]

	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]

	at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]

	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]

	at java.lang.Thread.run(Unknown Source) [?:?]

2021-08-08 22:19:40.179 [ERROR] [enhab.binding.astro.internal.job.Job] - Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@13b0817[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@9c2f3c[Wrapped task = Event job astro:sun:local/eveningNight#event/START]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@13b0817[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@9c2f3c[Wrapped task = Event job astro:sun:local/eveningNight#event/START]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Unknown Source) ~[?:?]

	at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(Unknown Source) ~[?:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.schedule(AstroThingHandler.java:307) ~[bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.schedule(Job.java:60) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleEvent(Job.java:109) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleEvent(Job.java:78) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleRange(Job.java:141) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.DailyJobSun.run(DailyJobSun.java:74) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.restartJobs(AstroThingHandler.java:203) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.initialize(AstroThingHandler.java:126) [bundleFile:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]

	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]

	at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]

	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]

	at java.lang.Thread.run(Unknown Source) [?:?]

2021-08-08 22:19:40.183 [ERROR] [enhab.binding.astro.internal.job.Job] - Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@977fbb[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1ed2b8a[Wrapped task = Sun phase job astro:sun:local/NIGHT]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@977fbb[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1ed2b8a[Wrapped task = Sun phase job astro:sun:local/NIGHT]] rejected from org.openhab.core.internal.common.WrappedScheduledExecutorService@18bba44[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2019874]

	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Unknown Source) ~[?:?]

	at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(Unknown Source) ~[?:?]

	at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(Unknown Source) ~[?:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.schedule(AstroThingHandler.java:307) ~[bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.schedule(Job.java:60) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.Job.scheduleSunPhase(Job.java:169) [bundleFile:?]

	at org.openhab.binding.astro.internal.job.DailyJobSun.run(DailyJobSun.java:92) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.restartJobs(AstroThingHandler.java:203) [bundleFile:?]

	at org.openhab.binding.astro.internal.handler.AstroThingHandler.initialize(AstroThingHandler.java:126) [bundleFile:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]

	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]

	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]

	at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]

	at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]

	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]

	at java.lang.Thread.run(Unknown Source) [?:?]

Expected Behavior

When daylight comes, the rule should be triggered

Current Behavior

daylight comes, rule is not triggered

Possible Solution

Steps to Reproduce (for Bugs)

I currently can reproduce it twice a day :)

Context

I tried reboot multiple times. I do have a snapshot "before" the upgrade.

Your Environment

  • Version used: (e.g., openHAB and add-on versions)
  • Environment name and version (e.g. Chrome 76, Java 8, Node.js 12.9, ...):
  • Operating System and version (desktop or mobile, Windows 10, Raspbian Buster, ...):

runtimeInfo: version: 3.2.0.M1 buildString: Milestone Build locale: de-DE systemInfo: configFolder: /etc/openhab userdataFolder: /var/lib/openhab logFolder: /var/log/openhab javaVersion: 11.0.12 javaVendor: Azul Systems, Inc. javaVendorVersion: Zulu11.50+19-CA osName: Linux osVersion: 5.4.78-2-pve osArchitecture: i386 availableProcessors: 1 freeMemory: 61513000 totalMemory: 202375168 bindings:

  • amazonechocontrol
  • astro
  • exec
  • http
  • lifx
  • logreader
  • miio
  • mqtt
  • network
  • openweathermap
  • shelly
  • smartmeter
  • telegram
  • yeelight clientInfo: device: ios: false android: false androidChrome: false desktop: true iphone: false ipod: false ipad: false edge: false ie: false firefox: false macos: false windows: true cordova: false phonegap: false electron: false nwjs: false webView: false webview: false standalone: false os: windows pixelRatio: 1 prefersColorScheme: light isSecureContext: false locationbarVisible: true menubarVisible: true navigator: cookieEnabled: true deviceMemory: N/A hardwareConcurrency: 4 language: de-DE languages:
    • de-DE
    • de
    • en-US
    • en
    • fr onLine: true platform: Win32 screen: width: 3840 height: 2160 colorDepth: 24 support: touch: false pointerEvents: true observer: true passiveListener: true gestures: false intersectionObserver: true themeOptions: dark: dark filled: true pageTransitionAnimation: default bars: light homeNavbar: default homeBackground: default expandableCardAnimation: default userAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36 timestamp: 2021-08-08T20:26:51.783Z

Thank you very much! PhiL

openPhiL avatar Aug 08 '21 20:08 openPhiL

@clinique Any chance this has been fixed in your recent changes, or you can take a quick look?

Skinah avatar Sep 30 '21 12:09 Skinah

I'll have a look at this. If I can solve, I'll do but Astro is such a beast...

clinique avatar Sep 30 '21 14:09 clinique

@Skinah : don't you think this issue could be linked to this : https://github.com/openhab/openhab-addons/issues/11152

clinique avatar Oct 01 '21 14:10 clinique

@openPhiL : to be sure it can be linked, can you try deactivating your other bindings (especially MIIO)

clinique avatar Oct 01 '21 14:10 clinique

This issue may be a double up of this other open issue https://github.com/openhab/openhab-addons/issues/7642

I don't use the Astro binding nor have I read the code before, so I was hoping you knew the beast well enough to have a look :) Just going purely on the ERROR the user above has posted....

RejectedExecutionException is thrown when line 307 of AstroThingHandler.java is executed.

This occurs if the threadpool/executor is shutdown, or has run out of available threads. I'm probably only posting what you already know, but yes if this binding is using a shared executor service and it gets shutdown like your posted issue suggests then that would cause the RejectedExecutionException.

@openPhiL Your running version: 3.2.0.M1 released on 2nd Aug A fix for the MIIO binding was merged on 27th Aug openHAB 3.2 milestone 2 was released on 6th Sept

Suggest you retest using the latest milestone. If you report that is is fixed, we may be able to close this and the other issue.

Skinah avatar Oct 02 '21 04:10 Skinah

Hi All. I'm happy to see this Issue got attention. I am currently on vacation and cannot retest until end of next week or so.

My setup has not changed (same bindings, rules, etc), I can upgrade to the current Milestone to see if the error was resolved (e..g. in the MIO binding or anywhere).

I have read the Miio issue, and I do think that could have been the error indeed!

Regarding your reasoning: wouldn't it be an benefitial approach to prevent this error from an architectural approach? I mean, if the executor is not available, start one, instead of failing. .. and if no threads are available, wait a bit.. in addition to protecting the shutdown method a bit more?

thanks for your support guys

openPhiL avatar Oct 02 '21 09:10 openPhiL

I am not the one to ask such questions to as I am not a professional programmer, have not used or looked at the Astro binding code and can't speak for the people who wrote them. If you wrote code assuming at all times that someone else may have accidentally broken a golden rule, the code would not be nice to read and it would not be fun to write code that way.

Skinah avatar Oct 02 '21 12:10 Skinah

Well gents, take it easy. @openPhiL : can you please just make the test with an updated version of MIIO binding ?

clinique avatar Oct 02 '21 12:10 clinique

This pr will stop it happening in future https://github.com/openhab/openhab-core/pull/2531

Skinah avatar Oct 24 '21 02:10 Skinah

Can we close this issue now that the mentioned PR in core repo was merged?

lolodomo avatar Oct 03 '22 11:10 lolodomo

No more feedback. Probably closed by the mentioned fix in core.

lolodomo avatar Dec 17 '22 09:12 lolodomo