Please discuss openHAB 4.0 SNAPSHOT related stuff here.
Please keep in mind, Java version 17 is needed now !
2 Likes
@hmerk, Thank you!
Iāll move the posts from the 3.4 thread over here.
OK, hereās my problems. Iām hoping there are something easy.
- Zwave: My Zwave controller thing comes up as OFFLINE. There are no errors in the longs and nothing unusual or unexpected. Iāve not yet captured debug logs but hereās the binding INFO level logs and
openhab.log
2022-12-20 11:22:30.386 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2022-12-20 11:22:48.504 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2022-12-20 11:22:48.505 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
events.log
2022-12-20 11:22:26.458 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZwaveApplianceModule2_Switch' changed from NULL to OFF
2022-12-20 11:22:27.385 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node11' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.388 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node13' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.390 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node12' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.392 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node6' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.394 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node8' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.461 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node7' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.504 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node2' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.508 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node4' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:27.528 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node3' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 11:22:31.000 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:zw_controller' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING
2022-12-20 11:22:31.028 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:zw_controller' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.046 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node6' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.048 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.052 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node8' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.054 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.056 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node3' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.058 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node8' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.060 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.061 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.064 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.065 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.067 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node4' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.068 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node12' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.070 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node11' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.071 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node13' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 11:22:31.072 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.073 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node13' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.074 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node12' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 11:22:31.075 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node11' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
It looks like the handler for the bridge is failing to initialize. which kills everything after that. I canāt remember if I used to see that āattempting to add listenerā line in previous versions of OH.
Iāve only just begun to investigate this one.
- I still have a few Nashorn Script Conditions in the UI. I installed the Nashorn add-on from the Marketplace. However, for each of them get a "ScriptEngine for language āapplication/javascriptā could not be found. JSScripting Nashorn is installed and shows as āActiveā in the karaf console.
This one isnāt really a problem but I want to mention it here for future readers of the thread. The JS transformation is replaced with the new SCRIPT transformation. See Transformations | openHAB.
Hereās a debug log from a startup
2022-12-20 12:25:53.603 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : BundleComponentActivator : ComponentHolder created.
2022-12-20 12:25:53.606 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2022-12-20 12:25:53.609 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created ConfigDescriptionRegistryinterface=org.openhab.core.config.core.ConfigDescriptionRegistry, filter=null, policy=static, cardinality=1..1, bind=setConfigDescriptionRegistry, unbind=unsetConfigDescriptionRegistry, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2022-12-20 12:25:53.611 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created ThingRegistryinterface=org.openhab.core.thing.ThingRegistry, filter=null, policy=static, cardinality=1..1, bind=setThingRegistry, unbind=unsetThingRegistry, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2022-12-20 12:25:53.613 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created ThingTypeRegistryinterface=org.openhab.core.thing.type.ThingTypeRegistry, filter=null, policy=static, cardinality=1..1, bind=setThingTypeRegistry, unbind=unsetThingTypeRegistry, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2022-12-20 12:25:53.615 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component created: DS=DS13, implementation=org.openhab.binding.zwave.internal.ZWaveConfigProvider, immediate=true, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.zwave.internal.ZWaveConfigProvider]
2022-12-20 12:25:53.616 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Services: scope=singleton, services=[org.openhab.core.config.core.ConfigDescriptionProvider, org.openhab.core.config.core.ConfigOptionProvider]
2022-12-20 12:25:53.619 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Properties: {}
2022-12-20 12:25:53.621 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2022-12-20 12:25:53.622 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2022-12-20 12:25:53.625 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component can not be activated since it is in state disabled
2022-12-20 12:25:53.626 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2022-12-20 12:25:53.626 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Updating target filters
2022-12-20 12:25:53.627 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : No change in target property for dependency ConfigDescriptionRegistry: currently registered: false
2022-12-20 12:25:53.627 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : No existing service listener to unregister for dependency ConfigDescriptionRegistry
2022-12-20 12:25:53.629 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Setting target property for dependency ConfigDescriptionRegistry to null
2022-12-20 12:25:53.629 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : New service tracker for ConfigDescriptionRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.config.core.ConfigDescriptionRegistry), initialReferenceFilter (objectClass=org.openhab.core.config.core.ConfigDescriptionRegistry)
2022-12-20 12:25:53.630 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ConfigDescriptionRegistry tracker reset (closed)
2022-12-20 12:25:53.632 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=227, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=106} (enter)
2022-12-20 12:25:53.632 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic active: false trackerOpened: false optional: false
2022-12-20 12:25:53.636 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=227, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=106} (exit)
2022-12-20 12:25:53.639 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ConfigDescriptionRegistry tracker opened
2022-12-20 12:25:53.639 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : registering service listener for dependency ConfigDescriptionRegistry
2022-12-20 12:25:53.641 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : No change in target property for dependency ThingRegistry: currently registered: false
2022-12-20 12:25:53.642 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : No existing service listener to unregister for dependency ThingRegistry
2022-12-20 12:25:53.643 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Setting target property for dependency ThingRegistry to null
2022-12-20 12:25:53.645 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : New service tracker for ThingRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.ThingRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.ThingRegistry)
2022-12-20 12:25:53.646 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingRegistry tracker reset (closed)
2022-12-20 12:25:53.647 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=364, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=243} (enter)
2022-12-20 12:25:53.652 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingRegistry tracking 2 SingleStatic active: false trackerOpened: false optional: false
2022-12-20 12:25:53.653 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=364, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=243} (exit)
2022-12-20 12:25:53.654 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingRegistry tracker opened
2022-12-20 12:25:53.658 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : registering service listener for dependency ThingRegistry
2022-12-20 12:25:53.659 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : No change in target property for dependency ThingTypeRegistry: currently registered: false
2022-12-20 12:25:53.661 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : No existing service listener to unregister for dependency ThingTypeRegistry
2022-12-20 12:25:53.663 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Setting target property for dependency ThingTypeRegistry to null
2022-12-20 12:25:53.664 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : New service tracker for ThingTypeRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.type.ThingTypeRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.type.ThingTypeRegistry)
2022-12-20 12:25:53.665 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingTypeRegistry tracker reset (closed)
2022-12-20 12:25:53.666 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=406, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=258} (enter)
2022-12-20 12:25:53.668 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingTypeRegistry tracking 3 SingleStatic active: false trackerOpened: false optional: false
2022-12-20 12:25:53.672 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=406, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=258} (exit)
2022-12-20 12:25:53.672 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : dm ThingTypeRegistry tracker opened
2022-12-20 12:25:53.675 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : registering service listener for dependency ThingTypeRegistry
2022-12-20 12:25:53.676 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Changed state from disabled to unsatisfiedReference
2022-12-20 12:25:53.677 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Component enabled
2022-12-20 12:25:53.677 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : ActivateInternal
2022-12-20 12:25:53.678 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.678 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.679 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Activating component from state unsatisfiedReference
2022-12-20 12:25:53.679 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.680 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.680 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Changed state from unsatisfiedReference to satisfied
2022-12-20 12:25:53.682 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : registration change queue [registered]
2022-12-20 12:25:53.685 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveConfigProvider()
2022-12-20 12:25:53.689 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveConfigProvider()
2022-12-20 12:25:53.693 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getting bind: setConfigDescriptionRegistry
2022-12-20 12:25:53.699 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Locating method setConfigDescriptionRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2022-12-20 12:25:53.700 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry
2022-12-20 12:25:53.704 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.framework.ServiceReference]) not found
2022-12-20 12:25:53.707 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2022-12-20 12:25:53.707 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getReferenceClass: Looking for interface class org.openhab.core.config.core.ConfigDescriptionRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2022-12-20 12:25:53.708 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getParameterClass: Found class org.openhab.core.config.core.ConfigDescriptionRegistry
2022-12-20 12:25:53.708 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.config.core.ConfigDescriptionRegistry
2022-12-20 12:25:53.709 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry)
2022-12-20 12:25:53.710 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry)
2022-12-20 12:25:53.711 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getting bind: setThingRegistry
2022-12-20 12:25:53.712 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Locating method setThingRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2022-12-20 12:25:53.713 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry
2022-12-20 12:25:53.714 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.framework.ServiceReference]) not found
2022-12-20 12:25:53.715 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2022-12-20 12:25:53.715 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getReferenceClass: Looking for interface class org.openhab.core.thing.ThingRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2022-12-20 12:25:53.716 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getParameterClass: Found class org.openhab.core.thing.ThingRegistry
2022-12-20 12:25:53.717 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.ThingRegistry
2022-12-20 12:25:53.717 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry)
2022-12-20 12:25:53.718 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry)
2022-12-20 12:25:53.719 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getting bind: setThingTypeRegistry
2022-12-20 12:25:53.726 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Locating method setThingTypeRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2022-12-20 12:25:53.729 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry
2022-12-20 12:25:53.730 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.framework.ServiceReference]) not found
2022-12-20 12:25:53.731 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2022-12-20 12:25:53.736 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getReferenceClass: Looking for interface class org.openhab.core.thing.type.ThingTypeRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2022-12-20 12:25:53.737 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getParameterClass: Found class org.openhab.core.thing.type.ThingTypeRegistry
2022-12-20 12:25:53.737 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.type.ThingTypeRegistry
2022-12-20 12:25:53.740 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry)
2022-12-20 12:25:53.741 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry)
2022-12-20 12:25:53.742 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : This thread collected dependencies
2022-12-20 12:25:53.745 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getService (single component manager) dependencies collected.
2022-12-20 12:25:53.746 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Querying state satisfied
2022-12-20 12:25:53.747 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Querying state satisfied
2022-12-20 12:25:53.747 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : For dependency ConfigDescriptionRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=227, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=106}] service: [org.openhab.core.config.core.ConfigDescriptionRegistry@3795c728]]]
2022-12-20 12:25:53.748 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : For dependency ThingRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.ThingRegistry}={service.id=364, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=243}] service: [org.openhab.core.thing.internal.ThingRegistryImpl@1a6e926d]]]
2022-12-20 12:25:53.749 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : For dependency ThingTypeRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.ThingTypeRegistry}={service.id=406, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=258}] service: [org.openhab.core.thing.type.ThingTypeRegistry@277666f0]]]
2022-12-20 12:25:53.801 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : invoking bind: setConfigDescriptionRegistry: parameters [org.openhab.core.config.core.ConfigDescriptionRegistry]
2022-12-20 12:25:53.802 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : invoked bind: setConfigDescriptionRegistry
2022-12-20 12:25:53.803 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : invoking bind: setThingRegistry: parameters [org.openhab.core.thing.internal.ThingRegistryImpl]
2022-12-20 12:25:53.806 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : invoked bind: setThingRegistry
2022-12-20 12:25:53.809 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : invoking bind: setThingTypeRegistry: parameters [org.openhab.core.thing.type.ThingTypeRegistry]
2022-12-20 12:25:53.810 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : invoked bind: setThingTypeRegistry
2022-12-20 12:25:53.810 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : getting activate: activate
2022-12-20 12:25:53.811 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2022-12-20 12:25:53.812 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-20 12:25:53.812 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Locating method activate in class java.lang.Object
2022-12-20 12:25:53.813 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-20 12:25:53.813 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : activate method [activate] not found, ignoring
2022-12-20 12:25:53.813 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Set implementation object for component
2022-12-20 12:25:53.814 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(334)] : Changed state from satisfied to active
2022-12-20 12:25:53.821 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Dependency Manager created SerialPortManagerinterface=org.openhab.core.io.transport.serial.SerialPortManager, filter=null, policy=static, cardinality=1..1, bind=setSerialPortManager, unbind=unsetSerialPortManager, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2022-12-20 12:25:53.822 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component created: DS=DS13, implementation=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.zwave.internal.ZWaveHandlerFactory]
2022-12-20 12:25:53.823 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2022-12-20 12:25:53.824 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Properties: {}
2022-12-20 12:25:53.825 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2022-12-20 12:25:53.827 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2022-12-20 12:25:53.828 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component can not be activated since it is in state disabled
2022-12-20 12:25:53.828 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2022-12-20 12:25:53.829 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Updating target filters
2022-12-20 12:25:53.831 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : No change in target property for dependency SerialPortManager: currently registered: false
2022-12-20 12:25:53.831 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : No existing service listener to unregister for dependency SerialPortManager
2022-12-20 12:25:53.832 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Setting target property for dependency SerialPortManager to null
2022-12-20 12:25:53.833 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : New service tracker for SerialPortManager, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.transport.serial.SerialPortManager), initialReferenceFilter (objectClass=org.openhab.core.io.transport.serial.SerialPortManager)
2022-12-20 12:25:53.834 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : dm SerialPortManager tracker reset (closed)
2022-12-20 12:25:53.835 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : dm SerialPortManager tracker opened
2022-12-20 12:25:53.837 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : registering service listener for dependency SerialPortManager
2022-12-20 12:25:53.838 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Changed state from disabled to unsatisfiedReference
2022-12-20 12:25:53.839 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Component enabled
2022-12-20 12:25:53.840 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : ActivateInternal
2022-12-20 12:25:53.841 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.841 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.842 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Activating component from state unsatisfiedReference
2022-12-20 12:25:53.843 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.844 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:53.845 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Dependency not satisfied: SerialPortManager
2022-12-20 12:25:53.846 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Not all dependencies satisfied, cannot activate
2022-12-20 12:25:54.748 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=638, service.bundleid=308, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=341} (enter)
2022-12-20 12:25:54.759 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : ActivateInternal
2022-12-20 12:25:54.761 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:54.766 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:54.768 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Activating component from state unsatisfiedReference
2022-12-20 12:25:54.771 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:54.776 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state unsatisfiedReference
2022-12-20 12:25:54.782 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Changed state from unsatisfiedReference to satisfied
2022-12-20 12:25:54.784 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : registration change queue [registered]
2022-12-20 12:25:54.789 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveHandlerFactory()
2022-12-20 12:25:54.794 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveHandlerFactory()
2022-12-20 12:25:54.795 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : getting bind: setSerialPortManager
2022-12-20 12:25:54.797 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Locating method setSerialPortManager in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2022-12-20 12:25:54.808 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager
2022-12-20 12:25:54.811 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.framework.ServiceReference]) not found
2022-12-20 12:25:54.815 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.service.component.ComponentServiceObjects]) not found
2022-12-20 12:25:54.822 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : getReferenceClass: Looking for interface class org.openhab.core.io.transport.serial.SerialPortManager through loader of org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2022-12-20 12:25:54.824 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : getParameterClass: Found class org.openhab.core.io.transport.serial.SerialPortManager
2022-12-20 12:25:54.825 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.io.transport.serial.SerialPortManager
2022-12-20 12:25:54.827 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager)
2022-12-20 12:25:54.830 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager)
2022-12-20 12:25:54.832 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : This thread collected dependencies
2022-12-20 12:25:54.845 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : getService (single component manager) dependencies collected.
2022-12-20 12:25:54.850 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state satisfied
2022-12-20 12:25:54.851 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Querying state satisfied
2022-12-20 12:25:54.856 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : For dependency SerialPortManager, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.serial.SerialPortManager}={service.id=638, service.bundleid=308, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=341}] service: [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl@65a044b7]]]
2022-12-20 12:25:54.858 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : invoking bind: setSerialPortManager: parameters [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl]
2022-12-20 12:25:54.864 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : invoked bind: setSerialPortManager
2022-12-20 12:25:54.865 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : getting activate: activate
2022-12-20 12:25:54.870 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2022-12-20 12:25:54.873 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-20 12:25:54.874 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2022-12-20 12:25:54.876 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2022-12-20 12:25:54.879 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2022-12-20 12:25:54.881 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : invoked activate: activate
2022-12-20 12:25:54.882 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Set implementation object for component
2022-12-20 12:25:54.884 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : Changed state from satisfied to active
2022-12-20 12:25:54.892 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202212191425 (302)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(335)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=638, service.bundleid=308, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=341} (exit)
2022-12-20 12:26:02.013 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:zw_controller with scan time of 60
2022-12-20 12:26:02.014 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:zw_controller
2022-12-20 12:26:02.021 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2022-12-20 12:26:02.789 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2022-12-20 12:26:02.795 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:zw_controller.
2022-12-20 12:26:02.883 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node2.
2022-12-20 12:26:02.884 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node8.
2022-12-20 12:26:02.887 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node3.
2022-12-20 12:26:02.943 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node4.
2022-12-20 12:26:02.945 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node13.
2022-12-20 12:26:02.952 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node12.
2022-12-20 12:26:02.953 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node7.
2022-12-20 12:26:02.959 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node6.
2022-12-20 12:26:03.008 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:zw_controller:node11.
2022-12-20 12:26:13.592 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2022-12-20 12:26:13.660 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2022-12-20 12:26:13.663 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2022-12-20 12:26:13.663 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2022-12-20 12:26:13.665 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2022-12-20 12:26:13.671 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2022-12-20 12:26:13.707 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2022-12-20 12:26:13.708 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2022-12-20 12:26:13.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-12-20 12:26:13.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-12-20 12:26:13.743 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2022-12-20 12:26:13.745 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2022-12-20 12:26:13.748 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 14 hours time.
2022-12-20 12:26:16.752 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2022-12-20 12:26:16.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2022-12-20 12:26:16.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-12-20 12:26:16.761 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9
2022-12-20 12:26:16.774 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-12-20 12:26:16.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2022-12-20 12:26:16.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2022-12-20 12:26:16.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-12-20 12:26:16.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2022-12-20 12:26:16.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-12-20 12:26:16.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2022-12-20 12:26:16.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-12-20 12:26:16.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2022-12-20 12:26:16.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-12-20 12:26:18.780 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 0: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2022-12-20 12:26:18.781 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 0: Transaction is current transaction, so clearing!!!!!
2022-12-20 12:26:18.781 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction CANCELLED
2022-12-20 12:26:18.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 CANCELLED
2022-12-20 12:26:18.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-12-20 12:26:18.866 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC
2022-12-20 12:26:18.916 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-12-20 12:26:18.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2022-12-20 12:26:20.944 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 1: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2022-12-20 12:26:20.965 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1: Transaction is current transaction, so clearing!!!!!
2022-12-20 12:26:20.966 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction CANCELLED
2022-12-20 12:26:20.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 CANCELLED
2022-12-20 12:26:21.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-12-20 12:26:21.147 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB
2022-12-20 12:26:21.238 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-12-20 12:26:21.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2022-12-20 12:26:23.240 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 2: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2022-12-20 12:26:23.240 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 2: Transaction is current transaction, so clearing!!!!!
2022-12-20 12:26:23.242 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction CANCELLED
2022-12-20 12:26:23.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 CANCELLED
2022-12-20 12:26:23.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-12-20 12:26:23.245 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65
2022-12-20 12:26:23.250 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-12-20 12:26:23.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2022-12-20 12:26:25.252 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 3: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2022-12-20 12:26:25.252 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 3: Transaction is current transaction, so clearing!!!!!
2022-12-20 12:26:25.253 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction CANCELLED
2022-12-20 12:26:25.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 CANCELLED
2022-12-20 12:26:25.254 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-12-20 12:26:25.255 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA
2022-12-20 12:26:25.259 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-12-20 12:26:25.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2022-12-20 12:26:27.269 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 4: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2022-12-20 12:26:27.269 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 4: Transaction is current transaction, so clearing!!!!!
2022-12-20 12:26:27.277 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4: Transaction CANCELLED
2022-12-20 12:26:27.278 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 CANCELLED
2022-12-20 12:26:27.278 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
There are a couple of ānot foundā logs mixed in there but they are debug level.
Hereās the corresponding events.log in case itās important.
2022-12-20 12:25:56.548 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZwaveApplianceModule2_Switch' changed from NULL to OFF
2022-12-20 12:26:00.803 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node11' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.821 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node13' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.826 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node12' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.838 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node6' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.842 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node8' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.901 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node7' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.914 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node2' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.916 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node4' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:00.965 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node3' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2022-12-20 12:26:02.778 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:zw_controller' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING
2022-12-20 12:26:02.830 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:zw_controller' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.854 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.855 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node3' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.878 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node8' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.888 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node8' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.899 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.913 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.922 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node13' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.923 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node6' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.925 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.945 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node12' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.949 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node4' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.950 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:02.951 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node13' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.954 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.955 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node12' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.963 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2022-12-20 12:26:02.975 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node11' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2022-12-20 12:26:03.018 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:zw_controller:node11' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
Minor update: Deleting and recreating the serial Thing does not change the behavior.
This log statement seems to be new. It popped up immeidately the usual āInitializing ZWaveā¦ā statements after recreating the Controller Thing.
2022-12-20 13:36:05.515 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:zw_controller
Unfortunately, Iām going to have to return to this tomorrow. I need the Christmas lights to work. 
If anyone has ideas for something for me to look at or try Iām all ears.
I donāt think there have been many changes to the Zwave binding so there has to be something different in core or with using Java 17 thatās causing problems I think.
openhab updated to 4.0.0-S3243 this morning on a rocky linux 8.7 system and doesnāt want to start up now.
(ADDED: Reverted back to 3.4.0-S3234 and itās all better now.)
The openhab.log file has:
2022-12-20 11:00:53.663 [ERROR] [ternal.service.BootFeaturesInstaller] - Error installing boot features
org.apache.felix.resolver.reason.ReasonException: Unable to resolve root: missing requirement [root] osgi.identity; osgi.identity=openhab-runtime-base; type=karaf.feature; version="[4.0.0.SNAPSHOT,4.0.0.SNAPSHOT]"; filter:="(&(osgi.identity=openhab-runtime-base)(type=karaf.feature)(version>=4.0.0.SNAPSHOT)(version<=4.0.0.SNAPSHOT))" [caused by: Unable to resolve openhab-runtime-base/4.0.0.SNAPSHOT: missing requirement [openhab-runtime-base/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=openhab-core-automation-module-script-rulesupport; type=karaf.feature [caused by: Unable to resolve openhab-core-automation-module-script-rulesupport/4.0.0.SNAPSHOT: missing requirement [openhab-core-automation-module-script-rulesupport/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=openhab-core-base; type=karaf.feature [caused by: Unable to resolve openhab-core-base/4.0.0.SNAPSHOT: missing requirement [openhab-core-base/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=org.openhab.core.automation; type=osgi.bundle; version="[4.0.0.202212191859,4.0.0.202212191859]"; resolution:=mandatory [caused by: Unable to resolve org.openhab.core.automation/4.0.0.202212191859: missing requirement [org.openhab.core.automation/4.0.0.202212191859] osgi.wiring.package; filter:="(&(osgi.wiring.package=org.openhab.core)(version>=4.0.0)(!(version>=5.0.0)))" [caused by: Unable to resolve org.openhab.core/4.0.0.202212191854: missing requirement [org.openhab.core/4.0.0.202212191854] osgi.ee; filter:="(&(osgi.ee=JavaSE)(version=17))"]]]]]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.ResolverImpl.doResolve(ResolverImpl.java:433) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.ResolverImpl.resolve(ResolverImpl.java:420) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.ResolverImpl.resolve(ResolverImpl.java:374) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.karaf.features.internal.region.SubsystemResolver.resolve(SubsystemResolver.java:257) ~[?:?]
at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:399) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1069) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:1004) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.apache.felix.resolver.reason.ReasonException: Unable to resolve openhab-runtime-base/4.0.0.SNAPSHOT: missing requirement [openhab-runtime-base/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=openhab-core-automation-module-script-rulesupport; type=karaf.feature [caused by: Unable to resolve openhab-core-automation-module-script-rulesupport/4.0.0.SNAPSHOT: missing requirement [openhab-core-automation-module-script-rulesupport/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=openhab-core-base; type=karaf.feature [caused by: Unable to resolve openhab-core-base/4.0.0.SNAPSHOT: missing requirement [openhab-core-base/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=org.openhab.core.automation; type=osgi.bundle; version="[4.0.0.202212191859,4.0.0.202212191859]"; resolution:=mandatory [caused by: Unable to resolve org.openhab.core.automation/4.0.0.202212191859: missing requirement [org.openhab.core.automation/4.0.0.202212191859] osgi.wiring.package; filter:="(&(osgi.wiring.package=org.openhab.core)(version>=4.0.0)(!(version>=5.0.0)))" [caused by: Unable to resolve org.openhab.core/4.0.0.202212191854: missing requirement [org.openhab.core/4.0.0.202212191854] osgi.ee; filter:="(&(osgi.ee=JavaSE)(version=17))"]]]]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
... 12 more
Caused by: org.apache.felix.resolver.reason.ReasonException: Unable to resolve openhab-core-automation-module-script-rulesupport/4.0.0.SNAPSHOT: missing requirement [openhab-core-automation-module-script-rulesupport/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=openhab-core-base; type=karaf.feature [caused by: Unable to resolve openhab-core-base/4.0.0.SNAPSHOT: missing requirement [openhab-core-base/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=org.openhab.core.automation; type=osgi.bundle; version="[4.0.0.202212191859,4.0.0.202212191859]"; resolution:=mandatory [caused by: Unable to resolve org.openhab.core.automation/4.0.0.202212191859: missing requirement [org.openhab.core.automation/4.0.0.202212191859] osgi.wiring.package; filter:="(&(osgi.wiring.package=org.openhab.core)(version>=4.0.0)(!(version>=5.0.0)))" [caused by: Unable to resolve org.openhab.core/4.0.0.202212191854: missing requirement [org.openhab.core/4.0.0.202212191854] osgi.ee; filter:="(&(osgi.ee=JavaSE)(version=17))"]]]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
... 12 more
Caused by: org.apache.felix.resolver.reason.ReasonException: Unable to resolve openhab-core-base/4.0.0.SNAPSHOT: missing requirement [openhab-core-base/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=org.openhab.core.automation; type=osgi.bundle; version="[4.0.0.202212191859,4.0.0.202212191859]"; resolution:=mandatory [caused by: Unable to resolve org.openhab.core.automation/4.0.0.202212191859: missing requirement [org.openhab.core.automation/4.0.0.202212191859] osgi.wiring.package; filter:="(&(osgi.wiring.package=org.openhab.core)(version>=4.0.0)(!(version>=5.0.0)))" [caused by: Unable to resolve org.openhab.core/4.0.0.202212191854: missing requirement [org.openhab.core/4.0.0.202212191854] osgi.ee; filter:="(&(osgi.ee=JavaSE)(version=17))"]]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
... 12 more
Caused by: org.apache.felix.resolver.reason.ReasonException: Unable to resolve org.openhab.core.automation/4.0.0.202212191859: missing requirement [org.openhab.core.automation/4.0.0.202212191859] osgi.wiring.package; filter:="(&(osgi.wiring.package=org.openhab.core)(version>=4.0.0)(!(version>=5.0.0)))" [caused by: Unable to resolve org.openhab.core/4.0.0.202212191854: missing requirement [org.openhab.core/4.0.0.202212191854] osgi.ee; filter:="(&(osgi.ee=JavaSE)(version=17))"]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
... 12 more
Caused by: org.apache.felix.resolver.reason.ReasonException: Unable to resolve org.openhab.core/4.0.0.202212191854: missing requirement [org.openhab.core/4.0.0.202212191854] osgi.ee; filter:="(&(osgi.ee=JavaSE)(version=17))"
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.resolver.Candidates$MissingRequirementError.toException(Candidates.java:1341) ~[org.eclipse.osgi-3.17.200.jar:?]
... 12 more
2022-12-20 11:00:57.215 [WARN ] [org.apache.felix.fileinstall ] - Error while starting bundle: file:/usr/share/openhab/addons/org.openhab.binding.icloud-3.3.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.icloud [26]
Unresolved requirement: Import-Package: org.openhab.core.cache
at org.eclipse.osgi.container.Module.start(Module.java:463) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:445) ~[org.eclipse.osgi-3.17.200.jar:?]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [bundleFile:3.7.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [bundleFile:3.7.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1221) [bundleFile:3.7.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:515) [bundleFile:3.7.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [bundleFile:3.7.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [bundleFile:3.7.4]Not sure where to start poking around to figure this out.
What are the steps to upgrade from 3.4.0 to snapshot 4.0.0?
There is a list of changes?
What about matter support?
Thanks in advance for the answers.
Besides requiring Java 17, 4.0 snapshot is basically identical to 3.4.0 final right now. No, there is no Matter support. Iām not aware of anyone that has even started looking at implementing it for openHAB, but you could search the forums for a few discussions on it.
1 Like
First three openhab log items are normal. But the last time stamp is after all the event logs. Is it still not working?
Installed java 17
But upgrading to latest snapshot give me the following error
Blockquote
2022-12-20 20:27:41.407 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing āopenhab-binding-exec, openhab-binding-bluetooth, openhab-binding-airquality, openhab-misc-openhabcloud, openhab-transformation-bin2json, openhab-binding-network, openhab-ui-habpanel, openhab-binding-shelly, openhab-binding-feed, openhab-binding-broadlinkthermostat, openhab-binding-mqtt, openhab-transformation-map, openhab-binding-ipcamera, openhab-binding-telegram, openhab-transformation-xslt, openhab-transformation-exec, openhab-binding-systeminfo, openhab-transformation-scale, openhab-persistence-jdbc-mysql, openhab-voice-googletts, openhab-binding-opensprinkler, openhab-binding-weatherunderground, openhab-automation-groovyscripting, openhab-transformation-xpath, openhab-binding-hpprinter, openhab-persistence-rrd4j, openhab-binding-ntp, openhab-binding-http, openhab-binding-astro, openhab-binding-androiddebugbridge, openhab-persistence-mapdb, openhab-automation-pidcontroller, openhab-binding-avmfritz, openhab-persistence-influxdb, openhab-automation-jsscripting, openhab-binding-chromecast, openhab-binding-nuki, openhab-binding-lgwebos, openhab-transformation-jinja, openhab-binding-upnpcontrol, openhab-binding-networkupstools, openhab-voice-voicerss, openhab-binding-mail, openhab-voice-googlestt, openhab-binding-wled, openhab-transformation-javascript, openhab-automation-jrubyscripting, openhab-transformation-regex, openhab-transformation-jsonpath, openhab-automation-jythonscripting, openhab-ui-basic, openhab-binding-openweathermap, openhab-binding-fineoffsetweatherstation, openhab-binding-gpstracker, openhab-binding-snmp, openhab-binding-weathercompanyā: Unable to resolve root: missing requirement [root] osgi.identity; osgi.identity=openhab-transformation-bin2json; type=karaf.feature; version=ā[4.0.0.SNAPSHOT,4.0.0.SNAPSHOT]ā; filter:=ā(&(osgi.identity=openhab-transformation-bin2json)(type=karaf.feature)(version>=4.0.0.SNAPSHOT)(version<=4.0.0.SNAPSHOT))ā [caused by: Unable to resolve openhab-transformation-bin2json/4.0.0.SNAPSHOT: missing requirement [openhab-transformation-bin2json/4.0.0.SNAPSHOT] osgi.identity; osgi.identity=org.openhab.transform.bin2json; type=osgi.bundle; version=ā[4.0.0.202212200820,4.0.0.202212200820]ā; resolution:=mandatory [caused by: Unable to resolve org.openhab.transform.bin2json/4.0.0.202212200820: missing requirement [org.openhab.transform.bin2json/4.0.0.202212200820] osgi.wiring.package; filter:=ā(&(osgi.wiring.package=com.google.gson)(version>=2.9.0)(!(version>=3.0.0)))ā]]
Correct, still not working.
Iāve restarted a couple of times but havenāt tried recreating the Things nor clearing the cache yet (I was playing with the REST API end point to set the logging but that doesnāt appear to survive a restart of OH).
Iāll go add the relevant events.log statement from this latest restart in case itās informativeā¦ Itās interesting that one of the Items linked to a Zwave switch was updated. Based on the startup, that seems late for a restoreOnStartup event.
There actually are some significant changes caused by that move to Java 17.
No
Some of the changes I am aware of:
- Java 17 is the base
- Nashorn is no longer included and needs to be installed from the Marketplace
- Thereās a bug in the JS Scripting file watcher which requires Nashorn to be installed if you have file based JS Scripting files
- There is no longer a JS transformation which has been replaced with a SCRIPT transformation which can use any rules language. This is part of core now, not separately installable.
- The SCRIPT transform cannot be used from a Profile so if you have transform profiles that use JS, do not upgrade right now.
Just to report some level of success, 4.0.0 seems to work just fine inside of docker. Official image pulled about an hour ago. Build #3243 for reference. All bindings came up clean.
1 Like
Does that mean - at least today - one needs to install this from the Marketplace to continue using Blockly?
Yes, on the OH 4 snapshot right now thatās true. There is ongoing work to migrate it to JS Scripting but itās still on Nashorn today.
Is Zwave among them? That can point to something unique in my config if it worked for you and not for me.
All good points.
TBF, SCRIPT transform is available in 3.4.0.
Can you point me to more context on this? jrubyscripting recently implemented its own script file watcher heavily based on the JS scripting one. Iām guessing itās a Nashorn vs. JS issue, but I want to be sure.
Right, but you could still use the JS transform. Now the JS transform is gone. Thatās my point. You have to use SCRIPT now.
I donāt know if there is an issue yet but see JS Scripting filewatcher in automation not working. Iām about a week behind in perusing the github issues. @J-N-K or @florian-h05 should be able to point you in the right direction.
Is inline SCRIPT transformation supported?
Can you define inline?
Iām successfully using it for the state description of an item:
Number:Angle Exterior_WindDirection "Wind Direction [SCRIPT(rb:compass.script):%s]" <wind> (gInflux) { channel="mqtt:topic:jhatch:weather:winddirection" }
compass.script:
# -*- mode: ruby -*-
# frozen_string_literal: true
input ||= nil
DIRECTIONS = %w[N NE E SE S SW W NW N].freeze
if input.nil? || input == "NULL" || input == "UNDEF"
"-"
else
cardinal = DIRECTIONS[(input.to_f / 45).round]
"#{cardinal} (#{input.to_i}Ā°)"
end
Inline script is where you donāt need to create a script file. Just write the script in the script declaration with a pipe character.
Obv only practical for super short one-liners
Iāve triggered some builds which could help with applying all dependency changes.
Maybe you can try again with 4.0.0-SNAPSHOT build # 3244?
If it does not yet fix your issue, posting some logging may help.
The snapshots are more unstable now than usual with all those changes. 
But thanks to those who want to help out with testing and providing feedback with these first OH4 builds. 
Will do but wonāt get to it tomorrow unfortunately. Logs to follow when I give it a try.
Yep, thatās why I wanted to try it. But I expected to have more problems with Blockly and Nashorn rather than problems with Zwave. Thankfully jumping back and forth is super easy.
That was only supported by the JS transform so Iād guess almost certainly this is not (ever?) supported. SCRIPT is also not supported in Profiles yet.
But, it does support passing additional arguments to the transform using standard URL style which is a huge boon. This opens the possibility of more generic transformation scripts.
1 Like
No, my zwave is on a remote openhab running 3.4 still. Sorry.