openhab / org.openhab.binding.zwave

openHAB binding for Z-Wave
Eclipse Public License 2.0
170 stars 202 forks source link

Zwave binding does not come back online after hard reset #1871

Open awaldfogel opened 1 year ago

awaldfogel commented 1 year ago

Set up the binding on OH 3.4 on a Pi4 with an Aeotec Gen5+ zwave stick.

Binding comes up and shows status ONLINE using either device /dev/ttyACM0 or udev symlink /dev/zwave. Expected behavior is that the binding reverts on reboot to its configured operation.

Problem: on a hard reset of the Pi, the binding does not come back online. Looked at the debug messages and the code, and it seems like the binding cannot reopen the device.

If I restarted on /dev/ttyACM0 and change the device to /dev/zwave then it restarts successfully.

However the failure for the binding to connect survives through OH restart and Pi reboot.

If I add a new udev symlink then the binding can connect to the device under the new name.

I don't know whether this is a problem with the binding, the OH serial library or the Java serial library, but it seems like a lock file is getting stuck and the binding could probably do something to clear out a stale lock.

For what it's worth, I have a UPS on the Pi, but as you know it's impossible to guarantee a computer will never hang or crash. Forum response is mostly "Make sure your computer never crashes"

Debug traces are posted on this thread: https://community.openhab.org/t/openhabian-rpi4-zwave-gen5-falls-offline-on-restart/146694/17

cdjackson commented 1 year ago

Please post the full logs here as the logs you reference aren't super helpful (pasted below for reference).

However it sounds like there's an issue with the udev links - the binding doesn't really have any control over these - it just tried to open the port that is defined - if the port isn't available, then it won't be able to open it, and this seems to be the case from your explanation above.

2023-05-18 15:07:04.459 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.

2023-05-18 15:07:04.461 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.

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

2023-05-18 15:07:04.452 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zwave:serial_zstick:3070fe8bd9’ changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING

2023-05-18 15:07:04.467 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zwave:serial_zstick:3070fe8bd9’ changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

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

2023-05-18 15:07:09.495 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port ‘/dev/zwave’

2023-05-18 15:07:09.528 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread

2023-05-18 15:07:09.537 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive

2023-05-18 15:07:09.540 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized

2023-05-18 15:07:09.547 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller

2023-05-18 15:07:09.580 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
awaldfogel commented 1 year ago

I did a fresh openhabian install for a simple reproduction of what I'm seeing. -> fresh install, turned off zram to eliminate file system cache issues. turned on zwave debug, inserted Gen5+ zwave and observed /dev/ttyACM0. Zwave is online

`BRING UP AND INITIAL INSTALL OF ZWAVE BINDING - ONLINE @ 16:18:10.547

2023-05-24 16:07:09.035 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007 2023-05-24 16:07:13.230 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started. 2023-05-24 16:07:16.222 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel 2023-05-24 16:08:08.382 [WARN ] [.io.rest.auth.internal.TokenResource] - Couldn't find a user with a session matching the provided refresh_token 2023-05-24 16:08:08.385 [WARN ] [.io.rest.auth.internal.TokenResource] - Token issuing failed: invalid_grant 2023-05-24 16:08:19.356 [INFO ] [p.auth.internal.AuthorizePageServlet] - First user account created: asher 2023-05-24 16:09:01.051 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Stopped HABPanel 2023-05-24 16:09:01.123 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI ==> /var/log/openhab/events.log <== ==> /var/log/openhab/openhab.log <== 2023-05-24 16:12:10.649 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007 2023-05-24 16:12:11.702 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started. 2023-05-24 16:12:19.424 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel 2023-05-24 16:17:12.580 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : BundleComponentActivator : ComponentHolder created. 2023-05-24 16:17:12.585 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : BundleComponentActivator : ComponentHolder created. 2023-05-24 16:17:12.589 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:17:12.590 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:17:12.592 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:17:12.594 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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] 2023-05-24 16:17:12.596 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Services: scope=singleton, services=[org.openhab.core.config.core.ConfigDescriptionProvider, org.openhab.core.config.core.ConfigOptionProvider] 2023-05-24 16:17:12.597 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Properties: {} 2023-05-24 16:17:12.599 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:17:12.601 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:17:12.603 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component can not be activated since it is in state disabled 2023-05-24 16:17:12.605 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:17:12.607 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Updating target filters 2023-05-24 16:17:12.608 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : No change in target property for dependency ConfigDescriptionRegistry: currently registered: false 2023-05-24 16:17:12.610 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : No existing service listener to unregister for dependency ConfigDescriptionRegistry 2023-05-24 16:17:12.612 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Setting target property for dependency ConfigDescriptionRegistry to null 2023-05-24 16:17:12.614 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : 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) 2023-05-24 16:17:12.616 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ConfigDescriptionRegistry tracker reset (closed) 2023-05-24 16:17:12.620 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=232, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107} (enter) 2023-05-24 16:17:12.623 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:17:12.625 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=232, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107} (exit) 2023-05-24 16:17:12.627 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ConfigDescriptionRegistry tracker opened 2023-05-24 16:17:12.629 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : registering service listener for dependency ConfigDescriptionRegistry 2023-05-24 16:17:12.631 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : No change in target property for dependency ThingRegistry: currently registered: false 2023-05-24 16:17:12.633 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : No existing service listener to unregister for dependency ThingRegistry 2023-05-24 16:17:12.636 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Setting target property for dependency ThingRegistry to null 2023-05-24 16:17:12.638 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : New service tracker for ThingRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.ThingRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.ThingRegistry) 2023-05-24 16:17:12.640 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingRegistry tracker reset (closed) 2023-05-24 16:17:12.644 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=366, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244} (enter) 2023-05-24 16:17:12.646 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingRegistry tracking 2 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:17:12.648 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=366, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244} (exit) 2023-05-24 16:17:12.650 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingRegistry tracker opened 2023-05-24 16:17:12.651 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : registering service listener for dependency ThingRegistry 2023-05-24 16:17:12.653 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : No change in target property for dependency ThingTypeRegistry: currently registered: false 2023-05-24 16:17:12.655 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : No existing service listener to unregister for dependency ThingTypeRegistry 2023-05-24 16:17:12.656 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Setting target property for dependency ThingTypeRegistry to null 2023-05-24 16:17:12.658 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : 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) 2023-05-24 16:17:12.660 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingTypeRegistry tracker reset (closed) 2023-05-24 16:17:12.663 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=403, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259} (enter) 2023-05-24 16:17:12.665 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingTypeRegistry tracking 3 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:17:12.667 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=403, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259} (exit) 2023-05-24 16:17:12.669 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : dm ThingTypeRegistry tracker opened 2023-05-24 16:17:12.671 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : registering service listener for dependency ThingTypeRegistry 2023-05-24 16:17:12.672 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Changed state from disabled to unsatisfiedReference 2023-05-24 16:17:12.674 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Component enabled 2023-05-24 16:17:12.676 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : ActivateInternal 2023-05-24 16:17:12.679 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.681 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.683 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Activating component from state unsatisfiedReference 2023-05-24 16:17:12.684 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.686 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.688 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Changed state from unsatisfiedReference to satisfied 2023-05-24 16:17:12.690 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : registration change queue [registered] 2023-05-24 16:17:12.698 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveConfigProvider() 2023-05-24 16:17:12.700 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveConfigProvider() 2023-05-24 16:17:12.702 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getting bind: setConfigDescriptionRegistry 2023-05-24 16:17:12.704 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Locating method setConfigDescriptionRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:17:12.705 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry 2023-05-24 16:17:12.712 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:17:12.714 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:17:12.715 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getReferenceClass: Looking for interface class org.openhab.core.config.core.ConfigDescriptionRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:17:12.717 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getParameterClass: Found class org.openhab.core.config.core.ConfigDescriptionRegistry 2023-05-24 16:17:12.719 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.config.core.ConfigDescriptionRegistry 2023-05-24 16:17:12.720 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry) 2023-05-24 16:17:12.722 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry) 2023-05-24 16:17:12.724 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getting bind: setThingRegistry 2023-05-24 16:17:12.725 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Locating method setThingRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:17:12.727 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry 2023-05-24 16:17:12.728 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:17:12.730 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:17:12.732 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getReferenceClass: Looking for interface class org.openhab.core.thing.ThingRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:17:12.733 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getParameterClass: Found class org.openhab.core.thing.ThingRegistry 2023-05-24 16:17:12.735 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.ThingRegistry 2023-05-24 16:17:12.736 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry) 2023-05-24 16:17:12.738 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry) 2023-05-24 16:17:12.740 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getting bind: setThingTypeRegistry 2023-05-24 16:17:12.741 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Locating method setThingTypeRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:17:12.743 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry 2023-05-24 16:17:12.745 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:17:12.746 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:17:12.748 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getReferenceClass: Looking for interface class org.openhab.core.thing.type.ThingTypeRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:17:12.749 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getParameterClass: Found class org.openhab.core.thing.type.ThingTypeRegistry 2023-05-24 16:17:12.751 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.type.ThingTypeRegistry 2023-05-24 16:17:12.752 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry) 2023-05-24 16:17:12.754 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry) 2023-05-24 16:17:12.756 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : This thread collected dependencies 2023-05-24 16:17:12.757 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getService (single component manager) dependencies collected. 2023-05-24 16:17:12.759 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Querying state satisfied 2023-05-24 16:17:12.760 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Querying state satisfied 2023-05-24 16:17:12.762 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : For dependency ConfigDescriptionRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=232, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107}] service: [org.openhab.core.config.core.ConfigDescriptionRegistry@e9d599]]] 2023-05-24 16:17:12.764 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : For dependency ThingRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.ThingRegistry}={service.id=366, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244}] service: [org.openhab.core.thing.internal.ThingRegistryImpl@3e94d8]]] 2023-05-24 16:17:12.765 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : For dependency ThingTypeRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.ThingTypeRegistry}={service.id=403, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259}] service: [org.openhab.core.thing.type.ThingTypeRegistry@44f2ec]]] 2023-05-24 16:17:12.852 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : invoking bind: setConfigDescriptionRegistry: parameters [org.openhab.core.config.core.ConfigDescriptionRegistry] 2023-05-24 16:17:12.854 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : invoked bind: setConfigDescriptionRegistry 2023-05-24 16:17:12.856 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : invoking bind: setThingRegistry: parameters [org.openhab.core.thing.internal.ThingRegistryImpl] 2023-05-24 16:17:12.857 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : invoked bind: setThingRegistry 2023-05-24 16:17:12.859 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : invoking bind: setThingTypeRegistry: parameters [org.openhab.core.thing.type.ThingTypeRegistry] 2023-05-24 16:17:12.861 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : invoked bind: setThingTypeRegistry 2023-05-24 16:17:12.862 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : getting activate: activate 2023-05-24 16:17:12.864 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:17:12.865 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:17:12.867 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Locating method activate in class java.lang.Object 2023-05-24 16:17:12.868 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:17:12.870 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : activate method [activate] not found, ignoring 2023-05-24 16:17:12.871 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Set implementation object for component 2023-05-24 16:17:12.873 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(311)] : Changed state from satisfied to active 2023-05-24 16:17:12.875 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:17:12.877 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[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] 2023-05-24 16:17:12.879 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory] 2023-05-24 16:17:12.880 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Properties: {} 2023-05-24 16:17:12.882 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:17:12.883 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:17:12.885 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component can not be activated since it is in state disabled 2023-05-24 16:17:12.886 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:17:12.888 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Updating target filters 2023-05-24 16:17:12.889 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : No change in target property for dependency SerialPortManager: currently registered: false 2023-05-24 16:17:12.891 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : No existing service listener to unregister for dependency SerialPortManager 2023-05-24 16:17:12.892 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Setting target property for dependency SerialPortManager to null 2023-05-24 16:17:12.894 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : 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) 2023-05-24 16:17:12.895 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : dm SerialPortManager tracker reset (closed) 2023-05-24 16:17:12.898 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=480, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=307} (enter) 2023-05-24 16:17:12.900 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : dm SerialPortManager tracking 1 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:17:12.902 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=480, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=307} (exit) 2023-05-24 16:17:12.903 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : dm SerialPortManager tracker opened 2023-05-24 16:17:12.905 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : registering service listener for dependency SerialPortManager 2023-05-24 16:17:12.906 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Changed state from disabled to unsatisfiedReference 2023-05-24 16:17:12.908 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Component enabled 2023-05-24 16:17:12.909 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : ActivateInternal 2023-05-24 16:17:12.911 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.912 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.914 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Activating component from state unsatisfiedReference 2023-05-24 16:17:12.915 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.917 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Querying state unsatisfiedReference 2023-05-24 16:17:12.918 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Changed state from unsatisfiedReference to satisfied 2023-05-24 16:17:12.920 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : registration change queue [registered] 2023-05-24 16:17:12.935 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveHandlerFactory() 2023-05-24 16:17:12.937 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveHandlerFactory() 2023-05-24 16:17:12.938 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : getting bind: setSerialPortManager 2023-05-24 16:17:12.940 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Locating method setSerialPortManager in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:17:12.941 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager 2023-05-24 16:17:12.943 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:17:12.945 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:17:12.946 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : getReferenceClass: Looking for interface class org.openhab.core.io.transport.serial.SerialPortManager through loader of org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:17:12.948 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : getParameterClass: Found class org.openhab.core.io.transport.serial.SerialPortManager 2023-05-24 16:17:12.949 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.io.transport.serial.SerialPortManager 2023-05-24 16:17:12.950 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager) 2023-05-24 16:17:12.952 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager) 2023-05-24 16:17:12.953 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : This thread collected dependencies 2023-05-24 16:17:12.955 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : getService (single component manager) dependencies collected. 2023-05-24 16:17:12.956 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Querying state satisfied 2023-05-24 16:17:12.958 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Querying state satisfied 2023-05-24 16:17:12.959 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : For dependency SerialPortManager, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.serial.SerialPortManager}={service.id=480, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=307}] service: [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl@155a102]]] 2023-05-24 16:17:12.961 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : invoking bind: setSerialPortManager: parameters [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl] 2023-05-24 16:17:12.963 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : invoked bind: setSerialPortManager 2023-05-24 16:17:12.964 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : getting activate: activate 2023-05-24 16:17:12.966 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:17:12.967 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:17:12.969 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory 2023-05-24 16:17:12.971 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext) 2023-05-24 16:17:12.972 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl] 2023-05-24 16:17:12.974 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : invoked activate: activate 2023-05-24 16:17:12.975 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Set implementation object for component 2023-05-24 16:17:12.977 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(312)] : Changed state from satisfied to active 2023-05-24 16:18:10.276 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No thing found in getConfigDescription thing:zwave:serial_zstick:f5082285e3 2023-05-24 16:18:10.385 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:f5082285e3 with scan time of 60 2023-05-24 16:18:10.388 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:f5082285e3 2023-05-24 16:18:10.391 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null ==> /var/log/openhab/events.log <== 2023-05-24 16:18:10.447 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:f5082285e3' changed from UNINITIALIZED to INITIALIZING ==> /var/log/openhab/openhab.log <== 2023-05-24 16:18:10.458 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller. 2023-05-24 16:18:10.461 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:f5082285e3. 2023-05-24 16:18:10.463 [DEBUG] [zwave.handler.ZWaveControllerHandler] - No network key set by user - using random value. ==> /var/log/openhab/events.log <== 2023-05-24 16:18:10.547 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:f5082285e3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline ==> /var/log/openhab/openhab.log <== 2023-05-24 16:18:15.567 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0' 2023-05-24 16:18:15.598 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread 2023-05-24 16:18:15.606 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive 2023-05-24 16:18:15.609 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized 2023-05-24 16:18:15.612 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller 2023-05-24 16:18:15.654 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller 2023-05-24 16:18:15.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:15.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:15.656 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false. 2023-05-24 16:18:15.658 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2023-05-24 16:18:15.660 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2023-05-24 16:18:15.663 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 10 hours time. 2023-05-24 16:18:18.659 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network 2023-05-24 16:18:18.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1 2023-05-24 16:18:18.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:18.696 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 2023-05-24 16:18:18.698 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 2023-05-24 16:18:18.701 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:18.702 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:18.703 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1 2023-05-24 16:18:18.709 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 36 2E 30 37 00 01 97 2023-05-24 16:18:18.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:18.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 36 2E 30 37 00 01 2023-05-24 16:18:18.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2 2023-05-24 16:18:18.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 36 2E 30 37 00 01 2023-05-24 16:18:18.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:18.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3 2023-05-24 16:18:18.733 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 36 2E 30 37 00 01 2023-05-24 16:18:18.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.739 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID 2023-05-24 16:18:18.741 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4 2023-05-24 16:18:18.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.762 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 6.07, Library Type=1 2023-05-24 16:18:18.764 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction COMPLETED 2023-05-24 16:18:18.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 65ms 2023-05-24 16:18:18.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 0: Transaction completed 2023-05-24 16:18:18.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 DONE 2023-05-24 16:18:18.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.780 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:18.782 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 2023-05-24 16:18:18.784 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 2023-05-24 16:18:18.786 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:18.787 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:18.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.792 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 01 20 C0 AC 37 6D 01 E1 2023-05-24 16:18:18.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:18.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=C0 AC 37 6D 01 2023-05-24 16:18:18.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=C0 AC 37 6D 01 2023-05-24 16:18:18.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:18.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.806 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=C0 AC 37 6D 01 2023-05-24 16:18:18.808 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xc0ac376d, Controller Node id = 1 2023-05-24 16:18:18.809 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction COMPLETED 2023-05-24 16:18:18.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 22ms 2023-05-24 16:18:18.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 1: Transaction completed 2023-05-24 16:18:18.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 DONE 2023-05-24 16:18:18.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:18.818 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 2023-05-24 16:18:18.819 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 2023-05-24 16:18:18.821 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:18.822 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:18.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:18.827 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 80 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00 90 2023-05-24 16:18:18.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 80 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00 2023-05-24 16:18:18.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 80 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00 2023-05-24 16:18:18.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:18.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.842 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 80 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00 2023-05-24 16:18:18.844 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version = 1.2 2023-05-24 16:18:18.846 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x86 2023-05-24 16:18:18.847 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type = 0x1 2023-05-24 16:18:18.849 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID = 0x5a 2023-05-24 16:18:18.851 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction COMPLETED 2023-05-24 16:18:18.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 5 to queue - size 3 2023-05-24 16:18:18.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 34ms 2023-05-24 16:18:18.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2: Transaction completed 2023-05-24 16:18:18.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 DONE 2023-05-24 16:18:18.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:18.869 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 2023-05-24 16:18:18.871 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 2023-05-24 16:18:18.872 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:18.873 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:18.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.877 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 2023-05-24 16:18:18.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 2023-05-24 16:18:18.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:18.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 2023-05-24 16:18:18.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:18.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.887 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 2023-05-24 16:18:18.889 [DEBUG] [age.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15 2023-05-24 16:18:18.890 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction COMPLETED 2023-05-24 16:18:18.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 18ms 2023-05-24 16:18:18.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 3: Transaction completed 2023-05-24 16:18:18.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 DONE 2023-05-24 16:18:18.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:18.903 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 2023-05-24 16:18:18.904 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 2023-05-24 16:18:18.905 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:18.906 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:18.907 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.910 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 56 01 AD 2023-05-24 16:18:18.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.912 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:18.912 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 2023-05-24 16:18:18.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 2023-05-24 16:18:18.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:18.917 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.918 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 2023-05-24 16:18:18.919 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response. 2023-05-24 16:18:18.921 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - NODE 1: Node is SUC. 2023-05-24 16:18:18.922 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4: Transaction COMPLETED 2023-05-24 16:18:18.923 [DEBUG] [ve.internal.protocol.ZWaveController] - SUC was not defined - using controller (NODE 1) 2023-05-24 16:18:18.925 [DEBUG] [etControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message 2023-05-24 16:18:18.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 6 to queue - size 2 2023-05-24 16:18:18.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:18.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 22ms 2023-05-24 16:18:18.929 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 4: Transaction completed 2023-05-24 16:18:18.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 DONE 2023-05-24 16:18:18.932 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.934 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:18.935 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE 2023-05-24 16:18:18.936 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE 2023-05-24 16:18:18.938 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:18.939 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:18.939 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:18.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:18.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:18.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:18.965 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2023-05-24 16:18:19.039 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 C0 2023-05-24 16:18:19.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 2023-05-24 16:18:19.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 2023-05-24 16:18:19.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:19.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.053 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 2023-05-24 16:18:19.055 [DEBUG] [age.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response. 2023-05-24 16:18:19.056 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found 2023-05-24 16:18:19.062 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API 2023-05-24 16:18:19.064 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller 2023-05-24 16:18:19.065 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------ 2023-05-24 16:18:19.067 [DEBUG] [age.SerialApiGetInitDataMessageClass] - # Nodes = 1 2023-05-24 16:18:19.068 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ---------------------------------------------------------------------------- 2023-05-24 16:18:19.070 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 5: Transaction COMPLETED 2023-05-24 16:18:19.074 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread start 2023-05-24 16:18:19.076 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting waiting for init threads 2023-05-24 16:18:19.076 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 137ms 2023-05-24 16:18:19.078 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init 2023-05-24 16:18:19.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 5: Transaction completed 2023-05-24 16:18:19.080 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:5 DONE 2023-05-24 16:18:19.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:19.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:19.096 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9 2023-05-24 16:18:19.101 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9 2023-05-24 16:18:19.104 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:19.104 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:19.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:19.107 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 3C C3 2023-05-24 16:18:19.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:19.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=3C 2023-05-24 16:18:19.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:19.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=3C 2023-05-24 16:18:19.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:19.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.131 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=3C 2023-05-24 16:18:19.136 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is secondary = false 2023-05-24 16:18:19.139 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is on other network = false 2023-05-24 16:18:19.142 [DEBUG] [etControllerCapabilitiesMessageClass] - Node ID Server is present = false 2023-05-24 16:18:19.145 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is real primary = true 2023-05-24 16:18:19.148 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is SUC = true 2023-05-24 16:18:19.151 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6: Transaction COMPLETED 2023-05-24 16:18:19.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 45ms 2023-05-24 16:18:19.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 6: Transaction completed 2023-05-24 16:18:19.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6 DONE 2023-05-24 16:18:19.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:19.163 [DEBUG] [l.initialization.ZWaveNodeSerializer] - Creating directory /var/lib/openhab/zwave 2023-05-24 16:18:19.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:19.329 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file /var/lib/openhab/zwave/network_c0ac376dnode_1.xml 2023-05-24 16:18:19.331 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Error serializing from file: file does not exist. 2023-05-24 16:18:19.371 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE 2023-05-24 16:18:19.374 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread finished 2023-05-24 16:18:19.374 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE 2023-05-24 16:18:19.376 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_1_init complete 2023-05-24 16:18:19.377 [DEBUG] [ve.internal.protocol.ZWaveController] - All init threads complete 2023-05-24 16:18:19.377 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting 2023-05-24 16:18:19.379 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true ==> /var/log/openhab/events.log <== 2023-05-24 16:18:19.384 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:f5082285e3' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab/openhab.log <== 2023-05-24 16:18:19.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@147a982 2023-05-24 16:18:19.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 7 to queue - size 1 2023-05-24 16:18:19.392 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:19.393 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 2023-05-24 16:18:19.395 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 2023-05-24 16:18:19.397 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2023-05-24 16:18:19.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.411 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2023-05-24 16:18:19.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:19.415 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 16 01 02 02 01 73 2023-05-24 16:18:19.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2023-05-24 16:18:19.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 01 02 02 01 2023-05-24 16:18:19.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2023-05-24 16:18:19.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 01 02 02 01 2023-05-24 16:18:19.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2023-05-24 16:18:19.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2023-05-24 16:18:19.426 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 01 02 02 01 2023-05-24 16:18:19.428 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo 2023-05-24 16:18:19.429 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = true 2023-05-24 16:18:19.430 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Routing = true 2023-05-24 16:18:19.431 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming = true 2023-05-24 16:18:19.433 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Version = 4 2023-05-24 16:18:19.434 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS = false 2023-05-24 16:18:19.435 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Security = false 2023-05-24 16:18:19.436 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud = 40000 2023-05-24 16:18:19.437 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Basic = BASIC_TYPE_STATIC_CONTROLLER 2023-05-24 16:18:19.439 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Generic = GENERIC_TYPE_STATIC_CONTROLLER 2023-05-24 16:18:19.440 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_PC_CONTROLLER 2023-05-24 16:18:19.442 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2023-05-24 16:18:19.445 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2023-05-24 16:18:19.446 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality. 2023-05-24 16:18:19.448 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2023-05-24 16:18:19.449 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC 2023-05-24 16:18:19.454 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2023-05-24 16:18:19.456 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2023-05-24 16:18:19.457 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 7: Transaction COMPLETED 2023-05-24 16:18:19.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 60ms 2023-05-24 16:18:19.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 7: Transaction completed 2023-05-24 16:18:19.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:7 DONE 2023-05-24 16:18:19.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2023-05-24 16:18:19.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 7: Transaction event listener: DONE: DONE -> UNINTIALIZED 2023-05-24 16:18:19.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2023-05-24 16:18:19.467 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1ff569b 2023-05-24 16:18:19.469 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE 2023-05-24 16:18:19.470 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation 2023-05-24 16:18:19.472 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DONE 2023-05-24 16:18:19.473 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab/zwave/network_c0ac376dnode_1.xml`

awaldfogel commented 1 year ago

Hard reset and zwave does not come back

`HARD RESET @ 16:20 - Initializing Zwave Serial Controller @ 16:22:48.792 but never comes ONLINE

2023-05-24 16:22:34.003 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007 2023-05-24 16:22:38.243 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started. 2023-05-24 16:22:41.174 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel 2023-05-24 16:22:41.226 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : BundleComponentActivator : ComponentHolder created. 2023-05-24 16:22:41.233 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : BundleComponentActivator : ComponentHolder created. 2023-05-24 16:22:41.248 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:22:41.251 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:22:41.253 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:22:41.256 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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] 2023-05-24 16:22:41.260 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Services: scope=singleton, services=[org.openhab.core.config.core.ConfigDescriptionProvider, org.openhab.core.config.core.ConfigOptionProvider] 2023-05-24 16:22:41.263 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Properties: {} 2023-05-24 16:22:41.265 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:22:41.268 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:22:41.271 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component can not be activated since it is in state disabled 2023-05-24 16:22:41.273 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:22:41.276 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Updating target filters 2023-05-24 16:22:41.279 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No change in target property for dependency ConfigDescriptionRegistry: currently registered: false 2023-05-24 16:22:41.281 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No existing service listener to unregister for dependency ConfigDescriptionRegistry 2023-05-24 16:22:41.284 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Setting target property for dependency ConfigDescriptionRegistry to null 2023-05-24 16:22:41.286 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : 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) 2023-05-24 16:22:41.289 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracker reset (closed) 2023-05-24 16:22:41.292 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=236, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107} (enter) 2023-05-24 16:22:41.295 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:22:41.297 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=236, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107} (exit) 2023-05-24 16:22:41.300 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracker opened 2023-05-24 16:22:41.302 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registering service listener for dependency ConfigDescriptionRegistry 2023-05-24 16:22:41.305 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No change in target property for dependency ThingRegistry: currently registered: false 2023-05-24 16:22:41.307 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No existing service listener to unregister for dependency ThingRegistry 2023-05-24 16:22:41.309 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Setting target property for dependency ThingRegistry to null 2023-05-24 16:22:41.312 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : New service tracker for ThingRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.ThingRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.ThingRegistry) 2023-05-24 16:22:41.314 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracker reset (closed) 2023-05-24 16:22:41.317 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=370, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244} (enter) 2023-05-24 16:22:41.320 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracking 2 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:22:41.323 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=370, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244} (exit) 2023-05-24 16:22:41.325 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracker opened 2023-05-24 16:22:41.327 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registering service listener for dependency ThingRegistry 2023-05-24 16:22:41.330 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No change in target property for dependency ThingTypeRegistry: currently registered: false 2023-05-24 16:22:41.332 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No existing service listener to unregister for dependency ThingTypeRegistry 2023-05-24 16:22:41.335 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Setting target property for dependency ThingTypeRegistry to null 2023-05-24 16:22:41.337 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : 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) 2023-05-24 16:22:41.340 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracker reset (closed) 2023-05-24 16:22:41.343 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=404, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259} (enter) 2023-05-24 16:22:41.346 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracking 3 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:22:41.348 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=404, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259} (exit) 2023-05-24 16:22:41.351 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracker opened 2023-05-24 16:22:41.353 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registering service listener for dependency ThingTypeRegistry 2023-05-24 16:22:41.356 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Changed state from disabled to unsatisfiedReference 2023-05-24 16:22:41.358 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Component enabled 2023-05-24 16:22:41.360 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : ActivateInternal 2023-05-24 16:22:41.362 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.364 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.366 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Activating component from state unsatisfiedReference 2023-05-24 16:22:41.367 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.368 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.370 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Changed state from unsatisfiedReference to satisfied 2023-05-24 16:22:41.372 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registration change queue [registered] 2023-05-24 16:22:41.380 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveConfigProvider() 2023-05-24 16:22:41.382 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveConfigProvider() 2023-05-24 16:22:41.384 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting bind: setConfigDescriptionRegistry 2023-05-24 16:22:41.385 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method setConfigDescriptionRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:22:41.387 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry 2023-05-24 16:22:41.395 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:22:41.397 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:22:41.399 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getReferenceClass: Looking for interface class org.openhab.core.config.core.ConfigDescriptionRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:22:41.401 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getParameterClass: Found class org.openhab.core.config.core.ConfigDescriptionRegistry 2023-05-24 16:22:41.403 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.config.core.ConfigDescriptionRegistry 2023-05-24 16:22:41.404 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry) 2023-05-24 16:22:41.406 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry) 2023-05-24 16:22:41.408 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting bind: setThingRegistry 2023-05-24 16:22:41.409 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method setThingRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:22:41.411 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry 2023-05-24 16:22:41.412 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:22:41.414 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:22:41.416 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getReferenceClass: Looking for interface class org.openhab.core.thing.ThingRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:22:41.417 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getParameterClass: Found class org.openhab.core.thing.ThingRegistry 2023-05-24 16:22:41.419 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.ThingRegistry 2023-05-24 16:22:41.421 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry) 2023-05-24 16:22:41.422 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry) 2023-05-24 16:22:41.424 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting bind: setThingTypeRegistry 2023-05-24 16:22:41.425 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method setThingTypeRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:22:41.427 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry 2023-05-24 16:22:41.428 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:22:41.430 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:22:41.432 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getReferenceClass: Looking for interface class org.openhab.core.thing.type.ThingTypeRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:22:41.433 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getParameterClass: Found class org.openhab.core.thing.type.ThingTypeRegistry 2023-05-24 16:22:41.435 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.type.ThingTypeRegistry 2023-05-24 16:22:41.436 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry) 2023-05-24 16:22:41.438 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry) 2023-05-24 16:22:41.440 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : This thread collected dependencies 2023-05-24 16:22:41.441 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getService (single component manager) dependencies collected. 2023-05-24 16:22:41.443 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state satisfied 2023-05-24 16:22:41.444 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state satisfied 2023-05-24 16:22:41.446 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : For dependency ConfigDescriptionRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=236, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107}] service: [org.openhab.core.config.core.ConfigDescriptionRegistry@ba734a]]] 2023-05-24 16:22:41.447 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : For dependency ThingRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.ThingRegistry}={service.id=370, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244}] service: [org.openhab.core.thing.internal.ThingRegistryImpl@19611d8]]] 2023-05-24 16:22:41.449 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : For dependency ThingTypeRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.ThingTypeRegistry}={service.id=404, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259}] service: [org.openhab.core.thing.type.ThingTypeRegistry@ecdce2]]] 2023-05-24 16:22:41.544 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoking bind: setConfigDescriptionRegistry: parameters [org.openhab.core.config.core.ConfigDescriptionRegistry] 2023-05-24 16:22:41.546 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoked bind: setConfigDescriptionRegistry 2023-05-24 16:22:41.547 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoking bind: setThingRegistry: parameters [org.openhab.core.thing.internal.ThingRegistryImpl] 2023-05-24 16:22:41.549 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoked bind: setThingRegistry 2023-05-24 16:22:41.551 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoking bind: setThingTypeRegistry: parameters [org.openhab.core.thing.type.ThingTypeRegistry] 2023-05-24 16:22:41.552 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoked bind: setThingTypeRegistry 2023-05-24 16:22:41.554 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting activate: activate 2023-05-24 16:22:41.555 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:22:41.557 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:22:41.559 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method activate in class java.lang.Object 2023-05-24 16:22:41.560 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:22:41.562 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : activate method [activate] not found, ignoring 2023-05-24 16:22:41.563 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Set implementation object for component 2023-05-24 16:22:41.565 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Changed state from satisfied to active 2023-05-24 16:22:41.567 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:22:41.568 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[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] 2023-05-24 16:22:41.570 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory] 2023-05-24 16:22:41.572 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Properties: {} 2023-05-24 16:22:41.573 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:22:41.575 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:22:41.576 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component can not be activated since it is in state disabled 2023-05-24 16:22:41.578 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:22:41.579 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Updating target filters 2023-05-24 16:22:41.581 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : No change in target property for dependency SerialPortManager: currently registered: false 2023-05-24 16:22:41.582 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : No existing service listener to unregister for dependency SerialPortManager 2023-05-24 16:22:41.584 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Setting target property for dependency SerialPortManager to null 2023-05-24 16:22:41.586 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : 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) 2023-05-24 16:22:41.587 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracker reset (closed) 2023-05-24 16:22:41.589 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracker opened 2023-05-24 16:22:41.591 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : registering service listener for dependency SerialPortManager 2023-05-24 16:22:41.592 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Changed state from disabled to unsatisfiedReference 2023-05-24 16:22:41.594 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Component enabled 2023-05-24 16:22:41.596 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : ActivateInternal 2023-05-24 16:22:41.598 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.599 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.601 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Activating component from state unsatisfiedReference 2023-05-24 16:22:41.602 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.604 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.605 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Dependency not satisfied: SerialPortManager 2023-05-24 16:22:41.607 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Not all dependencies satisfied, cannot activate 2023-05-24 16:22:41.753 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=488, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=312} (enter) 2023-05-24 16:22:41.755 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : ActivateInternal 2023-05-24 16:22:41.756 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.758 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.760 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Activating component from state unsatisfiedReference 2023-05-24 16:22:41.761 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.763 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:22:41.764 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Changed state from unsatisfiedReference to satisfied 2023-05-24 16:22:41.766 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : registration change queue [registered] 2023-05-24 16:22:41.783 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveHandlerFactory() 2023-05-24 16:22:41.784 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveHandlerFactory() 2023-05-24 16:22:41.786 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getting bind: setSerialPortManager 2023-05-24 16:22:41.787 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Locating method setSerialPortManager in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:22:41.789 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager 2023-05-24 16:22:41.791 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:22:41.793 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:22:41.795 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getReferenceClass: Looking for interface class org.openhab.core.io.transport.serial.SerialPortManager through loader of org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:22:41.796 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getParameterClass: Found class org.openhab.core.io.transport.serial.SerialPortManager 2023-05-24 16:22:41.798 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.io.transport.serial.SerialPortManager 2023-05-24 16:22:41.799 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager) 2023-05-24 16:22:41.801 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager) 2023-05-24 16:22:41.815 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : This thread collected dependencies 2023-05-24 16:22:41.816 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getService (single component manager) dependencies collected. 2023-05-24 16:22:41.818 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state satisfied 2023-05-24 16:22:41.819 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state satisfied 2023-05-24 16:22:41.844 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : For dependency SerialPortManager, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.serial.SerialPortManager}={service.id=488, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=312}] service: [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl@7ab2c4]]] 2023-05-24 16:22:41.846 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoking bind: setSerialPortManager: parameters [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl] 2023-05-24 16:22:41.848 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoked bind: setSerialPortManager 2023-05-24 16:22:41.849 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getting activate: activate 2023-05-24 16:22:41.851 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:22:41.853 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:22:41.855 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory 2023-05-24 16:22:41.857 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext) 2023-05-24 16:22:41.859 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl] 2023-05-24 16:22:41.861 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoked activate: activate 2023-05-24 16:22:41.863 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Set implementation object for component 2023-05-24 16:22:41.865 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Changed state from satisfied to active 2023-05-24 16:22:41.877 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=488, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=312} (exit) 2023-05-24 16:22:48.732 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:f5082285e3 with scan time of 60 2023-05-24 16:22:48.734 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:f5082285e3 2023-05-24 16:22:48.737 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null ==> /var/log/openhab/events.log <== 2023-05-24 16:22:48.783 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:f5082285e3' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING ==> /var/log/openhab/openhab.log <== 2023-05-24 16:22:48.792 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller. 2023-05-24 16:22:48.794 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:f5082285e3. ==> /var/log/openhab/events.log <== 2023-05-24 16:22:48.800 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:f5082285e3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline`

awaldfogel commented 1 year ago

tried adding a udev rule

ADDED A NEW UDEV RULE

SUBSYSTEM=="tty", ATTRS{idVendor}=="0658", ATTRS{idProduct}=="0200", SYMLINK+="zwave"

RELOADED RULES

sudo udevadm control --reload-rules sudo udevadm trigger

NEW DEVICE NOT IN /dev

SYSLOG SHOWS

May 24 16:27:53 openhabian karaf[611]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyACM0: File exists. It is NOT mine May 24 16:27:53 openhabian karaf[611]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyACM0: File exists. It is NOT mine May 24 16:28:23 openhabian karaf[611]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyACM0: File exists. It is NOT mine May 24 16:28:23 openhabian karaf[611]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyACM0: File exists. It is NOT mine

awaldfogel commented 1 year ago

Do you know where the lock files come from or if they're meant to clean up on a reboot? I rebooted and got this log file

`REBOOTED at 16:32 Initializing ZWAVE @ 16:33:30.457

==> /var/log/openhab/openhab.log <== 2023-05-24 16:33:15.843 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007 2023-05-24 16:33:22.928 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel 2023-05-24 16:33:22.980 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : BundleComponentActivator : ComponentHolder created. 2023-05-24 16:33:22.986 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : BundleComponentActivator : ComponentHolder created. 2023-05-24 16:33:22.990 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:33:22.993 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:33:22.995 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:33:22.998 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[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] 2023-05-24 16:33:23.000 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Services: scope=singleton, services=[org.openhab.core.config.core.ConfigDescriptionProvider, org.openhab.core.config.core.ConfigOptionProvider] 2023-05-24 16:33:23.003 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Properties: {} 2023-05-24 16:33:23.005 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:33:23.007 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:33:23.009 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component can not be activated since it is in state disabled 2023-05-24 16:33:23.011 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled 2023-05-24 16:33:23.013 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Updating target filters 2023-05-24 16:33:23.016 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No change in target property for dependency ConfigDescriptionRegistry: currently registered: false 2023-05-24 16:33:23.018 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No existing service listener to unregister for dependency ConfigDescriptionRegistry 2023-05-24 16:33:23.020 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Setting target property for dependency ConfigDescriptionRegistry to null 2023-05-24 16:33:23.023 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : 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) 2023-05-24 16:33:23.025 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracker reset (closed) 2023-05-24 16:33:23.028 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=236, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107} (enter) 2023-05-24 16:33:23.031 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:33:23.033 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=236, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107} (exit) 2023-05-24 16:33:23.035 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ConfigDescriptionRegistry tracker opened 2023-05-24 16:33:23.037 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registering service listener for dependency ConfigDescriptionRegistry 2023-05-24 16:33:23.040 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No change in target property for dependency ThingRegistry: currently registered: false 2023-05-24 16:33:23.042 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No existing service listener to unregister for dependency ThingRegistry 2023-05-24 16:33:23.044 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Setting target property for dependency ThingRegistry to null 2023-05-24 16:33:23.046 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : New service tracker for ThingRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.ThingRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.ThingRegistry) 2023-05-24 16:33:23.048 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracker reset (closed) 2023-05-24 16:33:23.051 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=370, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244} (enter) 2023-05-24 16:33:23.053 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracking 2 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:33:23.055 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=370, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244} (exit) 2023-05-24 16:33:23.057 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingRegistry tracker opened 2023-05-24 16:33:23.059 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registering service listener for dependency ThingRegistry 2023-05-24 16:33:23.061 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No change in target property for dependency ThingTypeRegistry: currently registered: false 2023-05-24 16:33:23.063 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : No existing service listener to unregister for dependency ThingTypeRegistry 2023-05-24 16:33:23.065 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Setting target property for dependency ThingTypeRegistry to null 2023-05-24 16:33:23.067 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : 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) 2023-05-24 16:33:23.069 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracker reset (closed) 2023-05-24 16:33:23.072 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=404, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259} (enter) 2023-05-24 16:33:23.074 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracking 3 SingleStatic active: false trackerOpened: false optional: false 2023-05-24 16:33:23.076 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=404, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259} (exit) 2023-05-24 16:33:23.078 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : dm ThingTypeRegistry tracker opened 2023-05-24 16:33:23.080 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registering service listener for dependency ThingTypeRegistry 2023-05-24 16:33:23.082 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Changed state from disabled to unsatisfiedReference 2023-05-24 16:33:23.084 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Component enabled 2023-05-24 16:33:23.086 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : ActivateInternal 2023-05-24 16:33:23.088 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.090 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.092 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Activating component from state unsatisfiedReference 2023-05-24 16:33:23.094 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.096 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.098 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Changed state from unsatisfiedReference to satisfied 2023-05-24 16:33:23.100 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : registration change queue [registered] 2023-05-24 16:33:23.111 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveConfigProvider() 2023-05-24 16:33:23.113 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveConfigProvider() 2023-05-24 16:33:23.115 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting bind: setConfigDescriptionRegistry 2023-05-24 16:33:23.118 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method setConfigDescriptionRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:33:23.120 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry 2023-05-24 16:33:23.131 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:33:23.133 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:33:23.135 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getReferenceClass: Looking for interface class org.openhab.core.config.core.ConfigDescriptionRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:33:23.137 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getParameterClass: Found class org.openhab.core.config.core.ConfigDescriptionRegistry 2023-05-24 16:33:23.140 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.config.core.ConfigDescriptionRegistry 2023-05-24 16:33:23.142 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry) 2023-05-24 16:33:23.144 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry) 2023-05-24 16:33:23.146 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting bind: setThingRegistry 2023-05-24 16:33:23.148 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method setThingRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:33:23.150 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry 2023-05-24 16:33:23.152 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:33:23.155 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:33:23.157 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getReferenceClass: Looking for interface class org.openhab.core.thing.ThingRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:33:23.159 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getParameterClass: Found class org.openhab.core.thing.ThingRegistry 2023-05-24 16:33:23.161 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.ThingRegistry 2023-05-24 16:33:23.162 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry) 2023-05-24 16:33:23.164 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry) 2023-05-24 16:33:23.166 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting bind: setThingTypeRegistry 2023-05-24 16:33:23.168 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method setThingTypeRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:33:23.170 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry 2023-05-24 16:33:23.171 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:33:23.173 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:33:23.175 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getReferenceClass: Looking for interface class org.openhab.core.thing.type.ThingTypeRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:33:23.177 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getParameterClass: Found class org.openhab.core.thing.type.ThingTypeRegistry 2023-05-24 16:33:23.179 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.type.ThingTypeRegistry 2023-05-24 16:33:23.180 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry) 2023-05-24 16:33:23.182 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry) 2023-05-24 16:33:23.184 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : This thread collected dependencies 2023-05-24 16:33:23.186 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getService (single component manager) dependencies collected. 2023-05-24 16:33:23.187 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state satisfied 2023-05-24 16:33:23.189 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Querying state satisfied 2023-05-24 16:33:23.191 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : For dependency ConfigDescriptionRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=236, service.bundleid=161, service.scope=bundle, component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=107}] service: [org.openhab.core.config.core.ConfigDescriptionRegistry@1e0f53e]]] 2023-05-24 16:33:23.193 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : For dependency ThingRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.ThingRegistry}={service.id=370, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=244}] service: [org.openhab.core.thing.internal.ThingRegistryImpl@9dfdaf]]] 2023-05-24 16:33:23.194 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : For dependency ThingTypeRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.ThingTypeRegistry}={service.id=404, service.bundleid=212, service.scope=bundle, component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=259}] service: [org.openhab.core.thing.type.ThingTypeRegistry@87487e]]] 2023-05-24 16:33:23.292 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoking bind: setConfigDescriptionRegistry: parameters [org.openhab.core.config.core.ConfigDescriptionRegistry] 2023-05-24 16:33:23.294 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoked bind: setConfigDescriptionRegistry 2023-05-24 16:33:23.296 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoking bind: setThingRegistry: parameters [org.openhab.core.thing.internal.ThingRegistryImpl] 2023-05-24 16:33:23.297 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoked bind: setThingRegistry 2023-05-24 16:33:23.299 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoking bind: setThingTypeRegistry: parameters [org.openhab.core.thing.type.ThingTypeRegistry] 2023-05-24 16:33:23.300 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : invoked bind: setThingTypeRegistry 2023-05-24 16:33:23.302 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : getting activate: activate 2023-05-24 16:33:23.303 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveConfigProvider 2023-05-24 16:33:23.305 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:33:23.306 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Locating method activate in class java.lang.Object 2023-05-24 16:33:23.308 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:33:23.309 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : activate method [activate] not found, ignoring 2023-05-24 16:33:23.311 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Set implementation object for component 2023-05-24 16:33:23.312 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(305)] : Changed state from satisfied to active 2023-05-24 16:33:23.314 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[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 2023-05-24 16:33:23.316 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[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] 2023-05-24 16:33:23.317 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory] 2023-05-24 16:33:23.319 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Properties: {} 2023-05-24 16:33:23.320 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:33:23.322 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:33:23.323 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component can not be activated since it is in state disabled 2023-05-24 16:33:23.325 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled 2023-05-24 16:33:23.326 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Updating target filters 2023-05-24 16:33:23.328 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : No change in target property for dependency SerialPortManager: currently registered: false 2023-05-24 16:33:23.329 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : No existing service listener to unregister for dependency SerialPortManager 2023-05-24 16:33:23.331 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Setting target property for dependency SerialPortManager to null 2023-05-24 16:33:23.333 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : 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) 2023-05-24 16:33:23.334 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracker reset (closed) 2023-05-24 16:33:23.336 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracker opened 2023-05-24 16:33:23.338 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : registering service listener for dependency SerialPortManager 2023-05-24 16:33:23.339 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Changed state from disabled to unsatisfiedReference 2023-05-24 16:33:23.341 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Component enabled 2023-05-24 16:33:23.343 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : ActivateInternal 2023-05-24 16:33:23.344 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.346 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.347 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Activating component from state unsatisfiedReference 2023-05-24 16:33:23.348 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.350 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.351 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Dependency not satisfied: SerialPortManager 2023-05-24 16:33:23.353 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Not all dependencies satisfied, cannot activate 2023-05-24 16:33:23.491 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=485, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=312} (enter) 2023-05-24 16:33:23.492 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : ActivateInternal 2023-05-24 16:33:23.494 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.495 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.497 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Activating component from state unsatisfiedReference 2023-05-24 16:33:23.499 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.501 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state unsatisfiedReference 2023-05-24 16:33:23.503 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Changed state from unsatisfiedReference to satisfied 2023-05-24 16:33:23.505 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : registration change queue [registered] 2023-05-24 16:33:23.522 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveHandlerFactory() 2023-05-24 16:33:23.524 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveHandlerFactory() 2023-05-24 16:33:23.525 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getting bind: setSerialPortManager 2023-05-24 16:33:23.527 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Locating method setSerialPortManager in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:33:23.528 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager 2023-05-24 16:33:23.531 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.framework.ServiceReference]) not found 2023-05-24 16:33:23.533 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.service.component.ComponentServiceObjects]) not found 2023-05-24 16:33:23.535 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getReferenceClass: Looking for interface class org.openhab.core.io.transport.serial.SerialPortManager through loader of org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:33:23.536 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getParameterClass: Found class org.openhab.core.io.transport.serial.SerialPortManager 2023-05-24 16:33:23.538 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.io.transport.serial.SerialPortManager 2023-05-24 16:33:23.539 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager) 2023-05-24 16:33:23.541 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager) 2023-05-24 16:33:23.555 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : This thread collected dependencies 2023-05-24 16:33:23.557 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getService (single component manager) dependencies collected. 2023-05-24 16:33:23.558 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state satisfied 2023-05-24 16:33:23.560 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Querying state satisfied 2023-05-24 16:33:23.562 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : For dependency SerialPortManager, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.serial.SerialPortManager}={service.id=485, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=312}] service: [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl@a83bfc]]] 2023-05-24 16:33:23.564 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoking bind: setSerialPortManager: parameters [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl] 2023-05-24 16:33:23.566 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoked bind: setSerialPortManager 2023-05-24 16:33:23.567 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : getting activate: activate 2023-05-24 16:33:23.569 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory 2023-05-24 16:33:23.571 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found 2023-05-24 16:33:23.572 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory 2023-05-24 16:33:23.574 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext) 2023-05-24 16:33:23.576 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl] 2023-05-24 16:33:23.578 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : invoked activate: activate 2023-05-24 16:33:23.579 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Set implementation object for component 2023-05-24 16:33:23.581 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : Changed state from satisfied to active 2023-05-24 16:33:23.592 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:3.4.4 (241)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(306)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=485, service.bundleid=246, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=312} (exit) 2023-05-24 16:33:25.484 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started. 2023-05-24 16:33:30.407 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:f5082285e3 with scan time of 60 2023-05-24 16:33:30.409 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:f5082285e3 2023-05-24 16:33:30.411 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null ==> /var/log/openhab/events.log <== 2023-05-24 16:33:30.448 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:f5082285e3' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING ==> /var/log/openhab/openhab.log <== 2023-05-24 16:33:30.457 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller. 2023-05-24 16:33:30.460 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:f5082285e3. ==> /var/log/openhab/events.log <== 2023-05-24 16:33:30.468 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:f5082285e3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline`

awaldfogel commented 1 year ago

Let me know if there are any other test you'd like me to run. Install is on an RPi4 with the latest firmware.

awaldfogel commented 1 year ago

FWIW I tried deleting

/var/lock/LCK…ttyACM0

and the binding can restart.

Apparently there's a script floating around to delete the LCK files on system start. Would it make sense for the zwave binding to delete lock files on initialization? I have no idea if the binding can see the absolute path or if there's some other risk from ignoring lock file status.

https://community.openhab.org/t/openhabian-rpi4-zwave-gen5-falls-offline-on-restart/146694/41

https://community.openhab.org/t/aeotec-z-wave-gen5-stick-stays-offline-after-container-restart-raspi-reboot/136990/19

cdjackson commented 1 year ago

The binding shouldn't be deleting lock files - they are actually there for a reason. I thought there had been a change to the driver to resolve the lock file issue, but in any case I think we can close this as it's not a binding issue.

awaldfogel commented 1 year ago

Is there any valid reason for lock files older than current system uptime? I wonder if a middle ground is to delete lock files older than uptime?

cdjackson commented 1 year ago

Again though - the binding shouldn't be trying to manage lock files. As I said earlier, I thought that there had been a fix to the lock file issue in the latest drivers, but this is in any case not something that bindings should be trying to resolve as COM ports are implemented differently for different environments.

awaldfogel commented 1 year ago

totally agree the binding shouldn't have to do this. But we can't seem to get anyone's attention to resolve lock files in the drivers.

On the OH forum I'm getting pushback that recovering from a hard reset is a non-goal for the platform. But it's kind of hard to guarantee hard resets never happen IRL.

I'm running 3.4.4 which I think is up-to-date.

cdjackson commented 1 year ago

I agree that the system should start properly from a hard reset, but also don't want to venture into the messy area of COM port implementations in the binding.

The binding doesn't know how a COM port is implemented - it's abstracted away by another OH serial port layer. So the binding can't know if there are lock files (windows doesn't use them at all) or where they are stored (different drivers put them in different places) so I don't think there's anything that can be done to resolve this in the binding without it being a big mess.

awaldfogel commented 1 year ago

Was afraid there might be some problem with too much abstraction.

Do you have any ability to poke the serial port maintainers? I'm implementing a workaround with a shell script in the init.d directory, but that feels like an even bigger hack. I also think this issue is worth documenting in the binding because I'm neither the first nor last person who will trip over failure to reset

awaldfogel commented 1 year ago

And before I forget: thanks for the work you're doing on the binding!

cdjackson commented 1 year ago

The intermediate layer is part of the OH core, but that's basically just a middle layer to allow the core to change the serial driver without impacting on the binding, so it just defers to another library.

I don't mind if you want to add something to the doc of the binding. The other option is to add it to OH docs since ultimately this issue will impact all serial port users and possibly the best thing is to document it in the main OH docs, and then refer to that in the binding docs.

https://www.openhab.org/docs/administration/serial.html#serial-port-configuration

awaldfogel commented 1 year ago

Is there a place a non-developer can open an issue with the serial core?

I feel like I'm a little out of my depth since the symptom I observe relates to operation of the zwave binding and I don't want the core to just bounce it back to me as "User error". I'm also hesitant to add something to the serial OH docs since I've only observed the lockup problem in this one place and don't have the bandwidth right now to search for broader anomalous serial behavior.

Unrelated but I had other issues with the serial binding. I couldn't pass control characters like "\n\r" and couldn't get any response on the OH forum, so I just gave up on the serial binding.

cdjackson commented 1 year ago

Is there a place a non-developer can open an issue with the serial core?

Sure - you can open an issue here -:

https://github.com/wborn/openhab-core/issues

You don't need to be a developer - it's the same as the issue you opened here

I feel like I'm a little out of my depth since the symptom I observe relates to operation of the zwave binding and I don't want the core to just bounce it back to me as "User error". I'

I don't see why it would be bounced as user error. In any case, as discussed above, I don't think the binding has any way to manage the lock files, so discussing it in the OH core, where teh serial libraries are provided, seems to me the best place. Of course, they might also point you further down into the actual low level driver - I don't know.

I'm also hesitant to add something to the serial OH docs since I've only observed the lockup problem in this one place and don't have the bandwidth right now to search for broader anomalous serial behavior.

Ok, that's fine. I was just suggesting adding your workaround regarding lock files to the docs.

awaldfogel commented 1 year ago

No response from the OH serial core group. Do you have any friends over there?