Z-Wave not working with OpenHAB 4.1.1

Uberschmutzer · March 4, 2024, 10:35pm

I’ve spent quite a while trying to get Z-Wave working on OpenHAB 4.1.1 without success. My system consists of an Intel NUC type platform running windows 11. I have tried 2 different Z-wave USB sticks, a Silicon Labs UZB-7 and a Zooz ZST39LR. The devices I’m using are an MP21ZD dimmer plug and a Zooz Zen77 800LR dimmer switch. To be sure, using the ZwaveController UI program that comes with Silicon Labs Simplicity Studio, I get everything to work reliably and properly with either USB stick.

I’ve followed the proper procedures (as far as I know) to add the bindings and things to openHab but I cannot get Z-Wave communication working at all. Does anyone have any tips on what I can try? I’m about to give up on OpenHAB.

TIA

rpwong · March 4, 2024, 11:06pm

Is there a particular reason for you to use Windows 11? The reason I ask is that most of us don’t use Windows for our openHAB servers. I assume there’s a missing link to enable openHAB to see your USB Z-Wave controller, but I’ve never done this so I can’t help you troubleshoot it.

To be clear, I’m not saying “you have to use Linux”. It’s just that using Linux brings you closer to what the majority of us do, and makes it easier to offer advice. If Linux is an option, I wouldn’t want you to give up on openHAB without trying it.

I run openHABian on a Raspberry Pi, specifically because I don’t have much expertise in Linux.

jswim788 · March 4, 2024, 11:28pm

Can you post your log files? Is there any Z-wave activity showing there?

Does your Z-wave controller Thing show up as online? Or is this the portion that doesn’t work?

Or does the controller come online, but you can’t communicate with the node devices?

Uberschmutzer · March 4, 2024, 11:55pm

I thought I’d work with a windows platform since I am more familiar with it than I am with Linux. The inexpensive NUC I purchased as a platform came with windows 11. I could run Linux as a virtual machine on that system. Would that be an improvement? l could also run the NUC as dual boot with Linux I suppose. Was trying the easiest thing for me at first. Which Linux distribution would you recommend?

Uberschmutzer · March 5, 2024, 12:03am

I’d be happy to post the log files on line. Since I’m new to OpenHAB, can you point me to directions or if simple enough, can you explain how to obtain them? So not sure about the Z-wave activity.

All the things, the controller and plug and switch all say they are online but none are identified, all appear to be unknown. Does this help diagnose the problem?

I appreciate your help on this.

jswim788 · March 5, 2024, 12:25am

I don’t use Windows for OH, so all I can do is point you to the docs for file locations. Hopefully you can find the logs as listed:

You see something like this in your Things?

It’s green and online?

I think we need to see your log files to understand better what is happening.

apella12 · March 5, 2024, 12:42am

Did you use Simplicity Studio to include devices? If yes need to exclude first.

Also if SS is running with OH there will be a serial device conflict.

Second the notion that debug log files are needed.

I have a test (only run periodically) OH environment on my PC using debian in WSL. For that I use usbipd wsl attach --busid 1-xx to allow the serial port into the WSL environment. Do you think OH has serial port access? (assuming you are not using containers?)

apella12 · March 5, 2024, 12:46am

before I mess with the log file. 1) Forget the event log 2) Use the </> to paint the openhab log.

Uberschmutzer · March 5, 2024, 12:50am

Did you use Simplicity Studio to include devices? If yes need to exclude first.
Have done this multiple times over course of testing. I use the remove button before switching or resetting plug and switch to factory settings

Also if SS is running with OH there will be a serial device conflict. It isn’t running

Second the notion that debug log files are needed.

I have a test (only run periodically) OH environment on my PC using debian in WSL. For that I use usbipd wsl attach --busid 1-xx to allow the serial port into the WSL environment. Do you think OH has serial port access? (assuming you are not using containers?) Yes, I can select the proper COM port when binding the stick
[/quote]

Uberschmutzer · March 5, 2024, 12:56am

2024-03-04 16:01:19.861 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.1.1 (build Release Build)
2024-03-04 16:01:20.273 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'America/Los_Angeles'.
2024-03-04 16:01:20.282 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '38.5186,-121.4987'.
2024-03-04 16:01:20.282 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2024-03-04 16:01:22.588 [WARN ] [org.openhab.core.net.NetUtil        ] - Found multiple local interfaces - ignoring 192.168.1.120
2024-03-04 16:01:35.566 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2024-03-04 16:01:38.556 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : BundleComponentActivator : ComponentHolder created.
2024-03-04 16:01:38.563 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2024-03-04 16:01:38.564 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[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
2024-03-04 16:01:38.564 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[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
2024-03-04 16:01:38.566 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[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
2024-03-04 16:01:38.567 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2024-03-04 16:01:38.568 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[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]
2024-03-04 16:01:38.569 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Services: scope=singleton, services=[org.openhab.core.config.core.ConfigDescriptionProvider, org.openhab.core.config.core.ConfigOptionProvider]
2024-03-04 16:01:38.569 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-03-04 16:01:38.569 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2024-03-04 16:01:38.570 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2024-03-04 16:01:38.570 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component can not be activated since it is in state disabled
2024-03-04 16:01:38.570 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2024-03-04 16:01:38.571 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Updating target filters
2024-03-04 16:01:38.571 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : No change in target property for dependency ConfigDescriptionRegistry: currently registered: false
2024-03-04 16:01:38.572 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] :  No existing service listener to unregister for dependency ConfigDescriptionRegistry
2024-03-04 16:01:38.572 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Setting target property for dependency ConfigDescriptionRegistry to null
2024-03-04 16:01:38.572 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : 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)
2024-03-04 16:01:38.573 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ConfigDescriptionRegistry tracker reset (closed)
2024-03-04 16:01:38.573 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=244, service.bundleid=166, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=112} (enter)
2024-03-04 16:01:38.574 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic active: false trackerOpened: false optional: false
2024-03-04 16:01:38.574 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=244, service.bundleid=166, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=112} (exit)
2024-03-04 16:01:38.574 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ConfigDescriptionRegistry tracker opened
2024-03-04 16:01:38.575 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : registering service listener for dependency ConfigDescriptionRegistry
2024-03-04 16:01:38.576 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : No change in target property for dependency ThingRegistry: currently registered: false
2024-03-04 16:01:38.576 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] :  No existing service listener to unregister for dependency ThingRegistry
2024-03-04 16:01:38.576 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Setting target property for dependency ThingRegistry to null
2024-03-04 16:01:38.577 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : New service tracker for ThingRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.ThingRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.ThingRegistry)
2024-03-04 16:01:38.577 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingRegistry tracker reset (closed)
2024-03-04 16:01:38.578 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=388, service.bundleid=219, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=263} (enter)
2024-03-04 16:01:38.578 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingRegistry tracking 2 SingleStatic active: false trackerOpened: false optional: false
2024-03-04 16:01:38.579 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=388, service.bundleid=219, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=263} (exit)
2024-03-04 16:01:38.579 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingRegistry tracker opened
2024-03-04 16:01:38.579 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : registering service listener for dependency ThingRegistry
2024-03-04 16:01:38.580 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : No change in target property for dependency ThingTypeRegistry: currently registered: false
2024-03-04 16:01:38.580 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] :  No existing service listener to unregister for dependency ThingTypeRegistry
2024-03-04 16:01:38.580 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Setting target property for dependency ThingTypeRegistry to null
2024-03-04 16:01:38.581 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : 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)
2024-03-04 16:01:38.581 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingTypeRegistry tracker reset (closed)
2024-03-04 16:01:38.582 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=421, service.bundleid=219, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=279} (enter)
2024-03-04 16:01:38.582 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingTypeRegistry tracking 3 SingleStatic active: false trackerOpened: false optional: false
2024-03-04 16:01:38.583 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=421, service.bundleid=219, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=279} (exit)
2024-03-04 16:01:38.583 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm ThingTypeRegistry tracker opened
2024-03-04 16:01:38.583 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : registering service listener for dependency ThingTypeRegistry
2024-03-04 16:01:38.584 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-03-04 16:01:38.584 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-03-04 16:01:38.584 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-03-04 16:01:38.585 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-03-04 16:01:38.585 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm osgi.ds.satisfying.condition tracking 4 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-03-04 16:01:38.586 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm osgi.ds.satisfying.condition tracking 4 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-03-04 16:01:38.586 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : dm osgi.ds.satisfying.condition tracker opened
2024-03-04 16:01:38.587 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-03-04 16:01:38.587 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Changed state from disabled to unsatisfiedReference
2024-03-04 16:01:38.588 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Component enabled
2024-03-04 16:01:38.588 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : ActivateInternal
2024-03-04 16:01:38.588 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.589 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.589 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Activating component from state unsatisfiedReference
2024-03-04 16:01:38.589 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.590 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.590 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Changed state from unsatisfiedReference to satisfied
2024-03-04 16:01:38.590 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : registration change queue [registered]
2024-03-04 16:01:38.594 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveConfigProvider()
2024-03-04 16:01:38.595 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveConfigProvider()
2024-03-04 16:01:38.596 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getting bind: setConfigDescriptionRegistry
2024-03-04 16:01:38.596 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Locating method setConfigDescriptionRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2024-03-04 16:01:38.596 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry
2024-03-04 16:01:38.599 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.framework.ServiceReference]) not found
2024-03-04 16:01:38.600 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2024-03-04 16:01:38.600 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.config.core.ConfigDescriptionRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2024-03-04 16:01:38.600 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getClassFromComponentClassLoader: Found class org.openhab.core.config.core.ConfigDescriptionRegistry
2024-03-04 16:01:38.601 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.config.core.ConfigDescriptionRegistry
2024-03-04 16:01:38.601 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry)
2024-03-04 16:01:38.602 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry)
2024-03-04 16:01:38.602 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getting bind: setThingRegistry
2024-03-04 16:01:38.602 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Locating method setThingRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2024-03-04 16:01:38.603 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry
2024-03-04 16:01:38.603 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.framework.ServiceReference]) not found
2024-03-04 16:01:38.604 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2024-03-04 16:01:38.604 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.thing.ThingRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2024-03-04 16:01:38.605 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getClassFromComponentClassLoader: Found class org.openhab.core.thing.ThingRegistry
2024-03-04 16:01:38.605 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.ThingRegistry
2024-03-04 16:01:38.606 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry)
2024-03-04 16:01:38.606 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry)
2024-03-04 16:01:38.606 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getting bind: setThingTypeRegistry
2024-03-04 16:01:38.607 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Locating method setThingTypeRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2024-03-04 16:01:38.607 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry
2024-03-04 16:01:38.607 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.framework.ServiceReference]) not found
2024-03-04 16:01:38.608 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2024-03-04 16:01:38.608 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.thing.type.ThingTypeRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2024-03-04 16:01:38.609 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getClassFromComponentClassLoader: Found class org.openhab.core.thing.type.ThingTypeRegistry
2024-03-04 16:01:38.609 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.type.ThingTypeRegistry
2024-03-04 16:01:38.609 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry)
2024-03-04 16:01:38.610 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry)
2024-03-04 16:01:38.610 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : This thread collected dependencies
2024-03-04 16:01:38.610 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getService (single component manager) dependencies collected.
2024-03-04 16:01:38.611 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Querying state satisfied
2024-03-04 16:01:38.611 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Querying state satisfied
2024-03-04 16:01:38.611 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : For dependency ConfigDescriptionRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=244, service.bundleid=166, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=112}] service: [org.openhab.core.config.core.ConfigDescriptionRegistry@1434a4e4]]]
2024-03-04 16:01:38.612 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : For dependency ThingRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.ThingRegistry}={service.id=388, service.bundleid=219, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=263}] service: [org.openhab.core.thing.internal.ThingRegistryImpl@790f1ebe]]]
2024-03-04 16:01:38.612 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : For dependency ThingTypeRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.ThingTypeRegistry}={service.id=421, service.bundleid=219, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=279}] service: [org.openhab.core.thing.type.ThingTypeRegistry@5765d08c]]]
2024-03-04 16:01:38.613 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-03-04 16:01:38.639 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : invoking bind: setConfigDescriptionRegistry: parameters [org.openhab.core.config.core.ConfigDescriptionRegistry]
2024-03-04 16:01:38.640 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : invoked bind: setConfigDescriptionRegistry
2024-03-04 16:01:38.640 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : invoking bind: setThingRegistry: parameters [org.openhab.core.thing.internal.ThingRegistryImpl]
2024-03-04 16:01:38.641 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : invoked bind: setThingRegistry
2024-03-04 16:01:38.641 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : invoking bind: setThingTypeRegistry: parameters [org.openhab.core.thing.type.ThingTypeRegistry]
2024-03-04 16:01:38.641 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : invoked bind: setThingTypeRegistry
2024-03-04 16:01:38.641 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : getting activate: activate
2024-03-04 16:01:38.642 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2024-03-04 16:01:38.642 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-03-04 16:01:38.642 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Locating method activate in class java.lang.Object
2024-03-04 16:01:38.642 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-03-04 16:01:38.642 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : activate method [activate] not found, ignoring
2024-03-04 16:01:38.644 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Set implementation object for component
2024-03-04 16:01:38.644 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(360)] : Changed state from satisfied to active
2024-03-04 16:01:38.644 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[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
2024-03-04 16:01:38.645 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2024-03-04 16:01:38.645 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[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]
2024-03-04 16:01:38.645 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2024-03-04 16:01:38.645 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-03-04 16:01:38.646 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2024-03-04 16:01:38.646 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2024-03-04 16:01:38.646 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component can not be activated since it is in state disabled
2024-03-04 16:01:38.647 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2024-03-04 16:01:38.647 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Updating target filters
2024-03-04 16:01:38.647 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : No change in target property for dependency SerialPortManager: currently registered: false
2024-03-04 16:01:38.647 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] :  No existing service listener to unregister for dependency SerialPortManager
2024-03-04 16:01:38.647 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Setting target property for dependency SerialPortManager to null
2024-03-04 16:01:38.648 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : 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)
2024-03-04 16:01:38.648 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm SerialPortManager tracker reset (closed)
2024-03-04 16:01:38.648 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=540, service.bundleid=262, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=355} (enter)
2024-03-04 16:01:38.649 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm SerialPortManager tracking 1 SingleStatic active: false trackerOpened: false optional: false
2024-03-04 16:01:38.649 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=540, service.bundleid=262, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=355} (exit)
2024-03-04 16:01:38.649 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm SerialPortManager tracker opened
2024-03-04 16:01:38.649 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : registering service listener for dependency SerialPortManager
2024-03-04 16:01:38.650 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-03-04 16:01:38.650 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-03-04 16:01:38.650 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-03-04 16:01:38.650 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-03-04 16:01:38.651 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-03-04 16:01:38.651 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-03-04 16:01:38.652 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : dm osgi.ds.satisfying.condition tracker opened
2024-03-04 16:01:38.652 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-03-04 16:01:38.652 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Changed state from disabled to unsatisfiedReference
2024-03-04 16:01:38.652 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Component enabled
2024-03-04 16:01:38.653 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : ActivateInternal
2024-03-04 16:01:38.653 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.653 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.653 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Activating component from state unsatisfiedReference
2024-03-04 16:01:38.653 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.654 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Querying state unsatisfiedReference
2024-03-04 16:01:38.654 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Changed state from unsatisfiedReference to satisfied
2024-03-04 16:01:38.654 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : registration change queue [registered]
2024-03-04 16:01:38.658 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveHandlerFactory()
2024-03-04 16:01:38.658 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveHandlerFactory()
2024-03-04 16:01:38.659 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : getting bind: setSerialPortManager
2024-03-04 16:01:38.659 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Locating method setSerialPortManager in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2024-03-04 16:01:38.659 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager
2024-03-04 16:01:38.659 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.framework.ServiceReference]) not found
2024-03-04 16:01:38.661 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.service.component.ComponentServiceObjects]) not found
2024-03-04 16:01:38.662 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.io.transport.serial.SerialPortManager through loader of org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2024-03-04 16:01:38.663 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : getClassFromComponentClassLoader: Found class org.openhab.core.io.transport.serial.SerialPortManager
2024-03-04 16:01:38.664 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.io.transport.serial.SerialPortManager
2024-03-04 16:01:38.665 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager)
2024-03-04 16:01:38.665 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager)
2024-03-04 16:01:38.666 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : This thread collected dependencies
2024-03-04 16:01:38.666 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : getService (single component manager) dependencies collected.
2024-03-04 16:01:38.666 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Querying state satisfied
2024-03-04 16:01:38.667 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Querying state satisfied
2024-03-04 16:01:38.667 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : For dependency SerialPortManager, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.serial.SerialPortManager}={service.id=540, service.bundleid=262, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=355}] service: [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl@2ec879f4]]]
2024-03-04 16:01:38.667 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-03-04 16:01:38.668 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : invoking bind: setSerialPortManager: parameters [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl]
2024-03-04 16:01:38.668 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : invoked bind: setSerialPortManager
2024-03-04 16:01:38.669 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : getting activate: activate
2024-03-04 16:01:38.669 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2024-03-04 16:01:38.669 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-03-04 16:01:38.670 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2024-03-04 16:01:38.670 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2024-03-04 16:01:38.670 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2024-03-04 16:01:38.670 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : invoked activate: activate
2024-03-04 16:01:38.671 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Set implementation object for component
2024-03-04 16:01:38.671 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.1.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(361)] : Changed state from satisfied to active
2024-03-04 16:01:42.720 [INFO ] [.internal.handler.Cm11aBridgeHandler] - Initialized CM11A X10 interface on: COM3
2024-03-04 16:01:42.750 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:18364cd37a with scan time of 60
2024-03-04 16:01:42.751 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:18364cd37a
2024-03-04 16:01:42.751 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2024-03-04 16:01:42.759 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2024-03-04 16:01:42.760 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:18364cd37a.
2024-03-04 16:01:42.778 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:18364cd37a:node1.
2024-03-04 16:01:42.783 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: MANUFACTURER not set
2024-03-04 16:01:42.784 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:18364cd37a:node3.
2024-03-04 16:01:42.784 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: MANUFACTURER not set
2024-03-04 16:01:45.659 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2024-03-04 16:01:47.767 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port 'COM5'
2024-03-04 16:01:47.777 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2024-03-04 16:01:47.778 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2024-03-04 16:01:47.779 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2024-03-04 16:01:47.779 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2024-03-04 16:01:47.785 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2024-03-04 16:01:47.785 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2024-03-04 16:01:47.786 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2024-03-04 16:01:47.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:47.786 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2024-03-04 16:01:47.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:47.787 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 10 hours time.
2024-03-04 16:01:50.787 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2024-03-04 16:01:50.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2024-03-04 16:01:50.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.797 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2024-03-04 16:01:50.804 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2024-03-04 16:01:50.805 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2024-03-04 16:01:50.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2024-03-04 16:01:50.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.807 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2024-03-04 16:01:50.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.808 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2024-03-04 16:01:50.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2024-03-04 16:01:50.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.809 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 37 2E 31 39 00 07 9F 
2024-03-04 16:01:50.809 [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 37 2E 31 39 00 07 
2024-03-04 16:01:50.811 [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 37 2E 31 39 00 07 
2024-03-04 16:01:50.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:50.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.812 [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 37 2E 31 39 00 07 
2024-03-04 16:01:50.816 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 7.19, Library Type=7
2024-03-04 16:01:50.817 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction COMPLETED
2024-03-04 16:01:50.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 12ms
2024-03-04 16:01:50.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 0: Transaction completed
2024-03-04 16:01:50.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 DONE
2024-03-04 16:01:50.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.819 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2024-03-04 16:01:50.819 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2024-03-04 16:01:50.820 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.822 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.823 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 20 D2 D1 43 AF 00 01 39 
2024-03-04 16:01:50.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D2 D1 43 AF 00 01 
2024-03-04 16:01:50.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D2 D1 43 AF 00 01 
2024-03-04 16:01:50.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:50.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.825 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D2 D1 43 AF 00 01 
2024-03-04 16:01:50.826 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xd2d143af, Controller Node id = 0
2024-03-04 16:01:50.826 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction COMPLETED
2024-03-04 16:01:50.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 6ms
2024-03-04 16:01:50.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 1: Transaction completed
2024-03-04 16:01:50.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 DONE
2024-03-04 16:01:50.827 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.827 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.827 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2024-03-04 16:01:50.827 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2024-03-04 16:01:50.828 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.829 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.834 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 01 14 02 7A 00 04 06 10 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 17 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 BF 
2024-03-04 16:01:50.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 14 02 7A 00 04 06 10 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 17 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2024-03-04 16:01:50.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 14 02 7A 00 04 06 10 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 17 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2024-03-04 16:01:50.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:50.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.838 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 14 02 7A 00 04 06 10 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 17 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2024-03-04 16:01:50.838 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version    = 1.20
2024-03-04 16:01:50.839 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x27a
2024-03-04 16:01:50.839 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type    = 0x4
2024-03-04 16:01:50.839 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID      = 0x610
2024-03-04 16:01:50.839 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction COMPLETED
2024-03-04 16:01:50.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 5 to queue - size 3
2024-03-04 16:01:50.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 12ms
2024-03-04 16:01:50.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2: Transaction completed
2024-03-04 16:01:50.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 DONE
2024-03-04 16:01:50.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.841 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2024-03-04 16:01:50.841 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2024-03-04 16:01:50.841 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.845 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.846 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 
2024-03-04 16:01:50.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2024-03-04 16:01:50.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2024-03-04 16:01:50.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:50.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.848 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2024-03-04 16:01:50.848 [DEBUG] [age.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15
2024-03-04 16:01:50.848 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction COMPLETED
2024-03-04 16:01:50.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 7ms
2024-03-04 16:01:50.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 3: Transaction completed
2024-03-04 16:01:50.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 DONE
2024-03-04 16:01:50.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.849 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2024-03-04 16:01:50.850 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2024-03-04 16:01:50.850 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.852 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.853 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 56 00 01 AC 
2024-03-04 16:01:50.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 01 
2024-03-04 16:01:50.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 01 
2024-03-04 16:01:50.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:50.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.855 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 01 
2024-03-04 16:01:50.856 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response.
2024-03-04 16:01:50.856 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - No SUC Node is set
2024-03-04 16:01:50.856 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4: Transaction COMPLETED
2024-03-04 16:01:50.856 [DEBUG] [ve.internal.protocol.ZWaveController] - SUC was not defined - using controller (NODE 0)
2024-03-04 16:01:50.856 [DEBUG] [etControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message
2024-03-04 16:01:50.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 6 to queue - size 2
2024-03-04 16:01:50.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 7ms
2024-03-04 16:01:50.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 4: Transaction completed
2024-03-04 16:01:50.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 DONE
2024-03-04 16:01:50.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.858 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE 
2024-03-04 16:01:50.858 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE 
2024-03-04 16:01:50.859 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.861 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.866 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 0A 08 1D 05 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 08 00 CB 
2024-03-04 16:01:50.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 08 1D 05 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 08 00 
2024-03-04 16:01:50.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 08 1D 05 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 08 00 
2024-03-04 16:01:50.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

Uberschmutzer · March 5, 2024, 12:57am

2024-03-04 16:01:50.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.868 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 08 1D 05 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 08 00 
2024-03-04 16:01:50.869 [DEBUG] [age.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response.
2024-03-04 16:01:50.869 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2024-03-04 16:01:50.869 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2024-03-04 16:01:50.870 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2024-03-04 16:01:50.870 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2024-03-04 16:01:50.871 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2024-03-04 16:01:50.871 [DEBUG] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2024-03-04 16:01:50.871 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2024-03-04 16:01:50.871 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 5: Transaction COMPLETED
2024-03-04 16:01:50.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 14ms
2024-03-04 16:01:50.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 5: Transaction completed
2024-03-04 16:01:50.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:5 DONE
2024-03-04 16:01:50.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.875 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9 
2024-03-04 16:01:50.875 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9 
2024-03-04 16:01:50.875 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread start
2024-03-04 16:01:50.876 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.876 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 3: Init node thread start
2024-03-04 16:01:50.877 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.878 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 1C E3 
2024-03-04 16:01:50.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 
2024-03-04 16:01:50.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 
2024-03-04 16:01:50.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:50.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.880 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 
2024-03-04 16:01:50.880 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is secondary = false
2024-03-04 16:01:50.880 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is on other network = false
2024-03-04 16:01:50.880 [DEBUG] [etControllerCapabilitiesMessageClass] - Node ID Server is present = false
2024-03-04 16:01:50.880 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is real primary = true
2024-03-04 16:01:50.881 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is SUC = true
2024-03-04 16:01:50.881 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6: Transaction COMPLETED
2024-03-04 16:01:50.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 5ms
2024-03-04 16:01:50.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 6: Transaction completed
2024-03-04 16:01:50.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6 DONE
2024-03-04 16:01:50.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.881 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting waiting for init threads
2024-03-04 16:01:50.883 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init
2024-03-04 16:01:50.965 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Serializing from file C:\OPENHA~1.1\userdata\zwave\network_d2d143af__node_3.xml
2024-03-04 16:01:50.966 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Error serializing from file: file does not exist.
2024-03-04 16:01:50.969 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file C:\OPENHA~1.1\userdata\zwave\network_d2d143af__node_1.xml
2024-03-04 16:01:50.969 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Error serializing from file: file does not exist.
2024-03-04 16:01:50.978 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Starting initialisation from EMPTYNODE
2024-03-04 16:01:50.978 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE
2024-03-04 16:01:50.979 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread finished
2024-03-04 16:01:50.979 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 3: Init node thread finished
2024-03-04 16:01:50.979 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_1_init complete
2024-03-04 16:01:50.980 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_3_init
2024-03-04 16:01:50.980 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_3_init complete
2024-03-04 16:01:50.980 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE
2024-03-04 16:01:50.980 [DEBUG] [ve.internal.protocol.ZWaveController] - All init threads complete
2024-03-04 16:01:50.980 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting
2024-03-04 16:01:50.980 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true
2024-03-04 16:01:50.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1a5b233f
2024-03-04 16:01:50.983 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE.
2024-03-04 16:01:50.983 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation.
2024-03-04 16:01:50.984 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties.
2024-03-04 16:01:50.984 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=2147483647
2024-03-04 16:01:50.984 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised
2024-03-04 16:01:50.985 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2024-03-04 16:01:50.985 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node...
2024-03-04 16:01:50.985 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Controller status changed to ONLINE.
2024-03-04 16:01:50.986 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Controller is ONLINE. Starting device initialisation.
2024-03-04 16:01:50.986 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Updating node properties.
2024-03-04 16:01:50.986 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Updating node properties. MAN=2147483647
2024-03-04 16:01:50.987 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Properties synchronised
2024-03-04 16:01:50.987 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2024-03-04 16:01:50.987 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Initialising Thing Node...
2024-03-04 16:01:50.988 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 86400 seconds - start in 39139200 milliseconds.
2024-03-04 16:01:50.988 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete.
2024-03-04 16:01:50.988 [WARN ] [.core.thing.binding.BaseThingHandler] - Attempt to apply invalid configuration 'Configuration[{key=controller_softreset; type=Boolean; value=false}, {key=security_networkkey; type=String; value=45 3D FA 66 4A B0 D6 70 AA FD E7 05 EF 23 31 1A}, {key=security_inclusionmode; type=BigDecimal; value=0}, {key=controller_sisnode; type=BigDecimal; value=0}, {key=controller_maxawakeperiod; type=BigDecimal; value=10}, {key=controller_sync; type=Boolean; value=false}, {key=controller_master; type=Boolean; value=true}, {key=inclusion_mode; type=BigDecimal; value=2}, {key=port; type=String; value=COM5}, {key=controller_wakeupperiod; type=BigDecimal; value=3600}, {key=controller_exclude; type=Boolean; value=false}, {key=heal_time; type=BigDecimal; value=2}, {key=controller_inclusiontimeout; type=BigDecimal; value=30}, {key=controller_hardreset; type=Boolean; value=false}]' on thing 'zwave:serial_zstick:18364cd37a' blocked. This is most likely a bug: {controller_sisnode=The value must not be less than 1.}
2024-03-04 16:01:50.988 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Polling initialised at 86400 seconds - start in 21686400 milliseconds.
2024-03-04 16:01:50.988 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Device initialisation complete.
2024-03-04 16:01:50.990 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to IDENTIFY_NODE
2024-03-04 16:01:50.990 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2024-03-04 16:01:50.991 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: Initialisation starting
2024-03-04 16:01:50.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@b046819
2024-03-04 16:01:50.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 7 to queue - size 1
2024-03-04 16:01:50.992 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:50.992 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 
2024-03-04 16:01:50.992 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 
2024-03-04 16:01:50.993 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:50.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 8 to queue - size 1
2024-03-04 16:01:50.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.995 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:50.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:50.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:50.996 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 01 41 00 00 00 03 00 00 00 B6 
2024-03-04 16:01:50.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2024-03-04 16:01:50.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2024-03-04 16:01:50.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:50.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:50.998 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2024-03-04 16:01:50.998 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo
2024-03-04 16:01:50.998 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = false
2024-03-04 16:01:50.998 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Routing   = false
2024-03-04 16:01:50.999 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming   = false
2024-03-04 16:01:50.999 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Version   = 1
2024-03-04 16:01:50.999 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS     = false
2024-03-04 16:01:50.999 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Security  = false
2024-03-04 16:01:50.999 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud  = 9600
2024-03-04 16:01:50.999 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Basic    = BASIC_TYPE_SLAVE
2024-03-04 16:01:50.999 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Generic  = GENERIC_TYPE_NOT_USED
2024-03-04 16:01:51.000 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_NOT_USED
2024-03-04 16:01:51.000 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2024-03-04 16:01:51.001 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2024-03-04 16:01:51.001 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality.
2024-03-04 16:01:51.002 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2024-03-04 16:01:51.002 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC
2024-03-04 16:01:51.003 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2024-03-04 16:01:51.004 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2024-03-04 16:01:51.004 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 7: Transaction COMPLETED
2024-03-04 16:01:51.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 11ms
2024-03-04 16:01:51.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 7: Transaction completed
2024-03-04 16:01:51.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:7 DONE
2024-03-04 16:01:51.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:51.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:51.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 7: Transaction event listener: DONE: DONE -> UNINTIALIZED
2024-03-04 16:01:51.005 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 03 B9 
2024-03-04 16:01:51.005 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 03 B9 
2024-03-04 16:01:51.007 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2024-03-04 16:01:51.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:51.009 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2024-03-04 16:01:51.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:51.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2024-03-04 16:01:51.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:51.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2024-03-04 16:01:51.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:51.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:51.011 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 01 41 00 00 00 03 00 00 00 B6 
2024-03-04 16:01:51.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2024-03-04 16:01:51.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2024-03-04 16:01:51.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:51.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2024-03-04 16:01:51.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2024-03-04 16:01:51.012 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2024-03-04 16:01:51.012 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: ProtocolInfo
2024-03-04 16:01:51.013 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Listening = false
2024-03-04 16:01:51.013 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Routing   = false
2024-03-04 16:01:51.013 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Beaming   = false
2024-03-04 16:01:51.013 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@518deb77
2024-03-04 16:01:51.013 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Version   = 1
2024-03-04 16:01:51.013 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE
2024-03-04 16:01:51.013 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: FLIRS     = false
2024-03-04 16:01:51.013 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Security  = false
2024-03-04 16:01:51.013 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to REQUEST_NIF
2024-03-04 16:01:51.013 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Max Baud  = 9600
2024-03-04 16:01:51.013 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 1: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2024-03-04 16:01:51.014 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Basic    = BASIC_TYPE_SLAVE
2024-03-04 16:01:51.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@21596c9e
2024-03-04 16:01:51.014 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Generic  = GENERIC_TYPE_NOT_USED
2024-03-04 16:01:51.014 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Specific = SPECIFIC_TYPE_NOT_USED
2024-03-04 16:01:51.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Bump transaction 9 priority from Controller to Immediate
2024-03-04 16:01:51.014 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2024-03-04 16:01:51.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
2024-03-04 16:01:51.014 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2024-03-04 16:01:51.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Added 9 to queue - size 1
2024-03-04 16:01:51.014 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Version = 1, version set. Enabling extra functionality.
2024-03-04 16:01:51.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2024-03-04 16:01:51.014 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2024-03-04 16:01:51.015 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_BASIC
2024-03-04 16:01:51.015 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2024-03-04 16:01:51.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2024-03-04 16:01:51.015 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 8: Transaction COMPLETED
2024-03-04 16:01:51.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 8ms
2024-03-04 16:01:51.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 8: Transaction completed
2024-03-04 16:01:51.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:8 DONE
2024-03-04 16:01:51.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2024-03-04 16:01:51.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:01:51.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 8: Transaction event listener: DONE: DONE -> UNINTIALIZED
2024-03-04 16:01:51.017 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1fc0369
2024-03-04 16:01:51.017 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE
2024-03-04 16:01:51.017 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to REQUEST_NIF
2024-03-04 16:01:51.017 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2024-03-04 16:01:51.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@44fe9d32
2024-03-04 16:01:51.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Bump transaction 10 priority from Controller to Immediate
2024-03-04 16:01:51.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2024-03-04 16:01:51.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 10 to queue - size 2
2024-03-04 16:01:51.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2024-03-04 16:10:21.917 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:18364cd37a
2024-03-04 16:11:35.865 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:18364cd37a

apella12 · March 5, 2024, 12:59am

{controller_sisnode=The value must not be less than 1.}

Heres one issue About halfway through. On the controller UI page enter 1. restart

Uberschmutzer · March 5, 2024, 1:19am

I’ve set that to 1 at various times, but it didn’t make a difference, but I will always do that now. Restarted and now I see it identifies my MP21ZD plug, which I’ve seen before, probably when I set SIS to 1 before. I continued with the process, and it seems to be working for the 1st time, although I’m pretty sure I’ve done this before but I must have done something wrong/differently.

I’ll try to get my wall switch on the network now.

So for now, thank you for your help!

apella12 · March 5, 2024, 1:26am

I did not see other problems in the debug, but Node 3 initialization was not complete because of the controller issue. No reason to ever change that, just leave as 1.

rpwong · March 5, 2024, 2:27am

The fact that @apella12 can help you with a Windows build makes this a lot easier, so you might as well get it sorted out. However, as you go deeper into openHAB, some of the things you read in the community may not line up exactly with a Windows system. For example, the file locations that @jswim788 mentioned earlier.

I don’t recommend a virtualized system for a permanent OH server. There’s no value to running Windows to run Linux to run openHAB. Same goes for dual-boot; you’re never going to boot Windows (because then openHAB is offline), so there’s no point.

If it were me, I’d install DietPi. From there, you can install openHAB from the DietPi launcher (along with a lot of other useful/interesting software). You could also try installing openHABian directly on any Debian Linux system (I haven’t done this, so I have no idea how well it works). The benefit of openHABian is that you’ll gain some useful features for maintaining your system, but lots of people don’t use it.

And with that…back to your Z-Wave issues.

Andrew_Rowe · March 5, 2024, 2:28am

Welcome to the community Neil!
First off, for the record, openHAB runs fine on Windows
If you like Windows, use Windows, plenty of folks in the forum use it and will provide support. No need for virtual machine or dual boot.

your Z-wave controller Thing shows up as online In openHAB right? Like shown in John’s post above. Sorry, just making sure.

Including the controller? or just the nodes?
Is this a new openHAB installation? Has openHAB ever run on this hardware? If it’s a brand new install on brand new hardware just wipe it and start over.

rpwong · March 5, 2024, 2:41am

Really? That’s not my impression, but I certainly don’t read every post.

For the record, I’m not at all anti-Windows.

rlkoshak · March 5, 2024, 4:03pm

It’s a minority for sure but there are several. Probably about the same number as run on Mac and there are even some intrepid users running on FreeBSD.

Andrew_Rowe · March 5, 2024, 6:56pm

I know of at least two binding developers (one also contributes to core) who use Windows as well, openHAB is not lacking support for Windows users

justaoldman · March 7, 2024, 3:07am

Hi,
Please do not let any one sway you to using an OS you are not comfortable with.
The learning curve for OpenHab is enough on its own without adding the learning or struggling with a unfamiliar OS to the challenge.
There is no problem running Openhab on windows.
I run a instance on windows to test with because “it is easy to clone an install” basically copy contents of install to a different folder and name (can be anything) with the openhab shut down and you have a second full blown self contained “play version” or fully functional backup and all I have had to do is shut down one and the start the copy easy and painless.back up approach.
Are there a few nuisances with running on windows sure same as with any OS windows I mainly saw was mostly with exec binding but otherwise none that I have found, and I have been running windows versions as test since 2.5.
Upgrade is easy with windows it is a 1 liner from a command prompt in"c:\<you parent folder\ runtime\bin" folder you run update and version you desire ie. “update 4.1.1” would update you to stable 4.1.1 version super easy and it upgrades that easy.
There are also good documents on how to install Openhab as a windows service, so it starts and shuts down on its own with windows again easy.
I also run a Linux version and a docker and a RPI with openhabian again all work fine.
Basically, pretty much if you can get correct java version installed fully and correctly on a OS it will likely run OpenHab
FYI I also run a zwave aero 5 usb stick on a windows 7 to windows 10 to 11 upgrade install and have had no issues with it going all the way back to 3.1 openhab upgraded all the way to OpenHAb 4.2.0 -snapshot.
As well as a pure windows 11 install from scratch and clean load 4.1.1 stable.
Oh, And regard to a downgrade to older version like say a 3.4.x is just as easy change your java environment variable to correct java install and shutdown 4.1.X and start up 3.4.X use same external devices with no issues…
SO, you should be just fine with what you have.
One last suggestion I will offer is download a copy of Notepad++ use it as your editor instead of windows notepad. You may also want to download a recent copy of Putty as your terminal emulator (so if you add Openhab as a service at some point you can connect to the console easily).