Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
awaldfogel opened this issue May 23, 2023 · 18 comments
Open

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

awaldfogel opened this issue May 23, 2023 · 18 comments

Comments

@awaldfogel
Copy link

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
Copy link
Collaborator

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
Copy link
Author

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_c0ac376d__node_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_c0ac376d__node_1.xml`

@awaldfogel
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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
Copy link
Collaborator

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
Copy link
Author

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
Copy link
Collaborator

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
Copy link
Author

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
Copy link
Collaborator

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
Copy link
Author

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
Copy link
Author

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

@cdjackson
Copy link
Collaborator

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
Copy link
Author

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
Copy link
Collaborator

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
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants