Z-Wave Shutting Down -- OH2 B1

[carpenike]

Hey All,

I'm not sure if this is the right place to ask a question about the Z-Wave binding itself, if not please re-direct me to where I should ask!

It appears that the 1.9 Z-Wave binding installed via the PaperUI console does not stay running on my fresh install. It configures, log shows that it comes up fine, but then it immediately shuts down.

Is this a known issue?

14:01:07.519 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyACM0
14:01:07.520 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, healtime = 2
14:01:07.523 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, softReset = false
14:01:07.523 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, masterController = true
14:01:07.526 [INFO ] [ve.internal.protocol.ZWaveController] - Starting Z-Wave controller
14:01:07.527 [INFO ] [ve.internal.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
14:01:07.528 [INFO ] [ve.internal.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
14:01:07.530 [INFO ] [b.core.service.AbstractActiveService] - ZWave Refresh Service has been started
14:01:07.541 [INFO ] [ve.internal.protocol.ZWaveController] - Serial port is initialized
14:01:08.564 [INFO ] [ve.internal.protocol.ZWaveController] - Disconnected from serial port
14:01:08.564 [INFO ] [ve.internal.protocol.ZWaveController] - Stopped Z-Wave controller
14:01:08.568 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyACM0
14:01:08.569 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, healtime = 2
14:01:08.571 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, softReset = false
14:01:08.573 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, masterController = true
14:01:08.576 [INFO ] [ve.internal.protocol.ZWaveController] - Starting Z-Wave controller
14:01:08.577 [INFO ] [ve.internal.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
14:01:08.578 [INFO ] [ve.internal.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
14:01:08.580 [INFO ] [b.core.service.AbstractActiveService] - ZWave Refresh Service has been started
14:01:08.591 [INFO ] [ve.internal.protocol.ZWaveController] - Serial port is initialized
14:01:09.612 [INFO ] [ve.internal.protocol.ZWaveController] - Disconnected from serial port
14:01:09.612 [INFO ] [ve.internal.protocol.ZWaveController] - Stopped Z-Wave controller
14:01:12.534 [INFO ] [b.core.service.AbstractActiveService] - ZWave Refresh Service has been shut down
14:01:13.581 [INFO ] [b.core.service.AbstractActiveService] - ZWave Refresh Service has been shut down

[cdjackson]

Haven't seen this before. Can you provide a debug log please.

Sent from my iPhone

On 13 Jan 2016, at 20:01, Ryan Holt notifications@github.com wrote:

Hey All,

I'm not sure if this is the right place to ask a question about the Z-Wave binding itself, if not please re-direct me to where I should ask!

It appears that the 19 Z-Wave binding installed via the PaperUI console does not stay running on my fresh install It configures, log shows that it comes up fine, but then it immediately shuts down

Is this a known issue?

14:01:07519 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, port = /dev/ttyACM0 14:01:07520 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, healtime = 2 14:01:07523 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, softReset = false 14:01:07523 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, masterController = true 14:01:07526 [INFO ] [veinternalprotocolZWaveController] - Starting Z-Wave controller 14:01:07527 [INFO ] [veinternalprotocolZWaveController] - Z-Wave timeout is set to 5000ms Soft reset is false 14:01:07528 [INFO ] [veinternalprotocolZWaveController] - Connecting to serial port /dev/ttyACM0 14:01:07530 [INFO ] [bcoreserviceAbstractActiveService] - ZWave Refresh Service has been started 14:01:07541 [INFO ] [veinternalprotocolZWaveController] - Serial port is initialized 14:01:08564 [INFO ] [veinternalprotocolZWaveController] - Disconnected from serial port 14:01:08564 [INFO ] [veinternalprotocolZWaveController] - Stopped Z-Wave controller 14:01:08568 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, port = /dev/ttyACM0 14:01:08569 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, healtime = 2 14:01:08571 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, softReset = false 14:01:08573 [INFO ] [ngzwaveinternalZWaveActiveBinding] - Update config, masterController = true 14:01:08576 [INFO ] [veinternalprotocolZWaveController] - Starting Z-Wave controller 14:01:08577 [INFO ] [veinternalprotocolZWaveController] - Z-Wave timeout is set to 5000ms Soft reset is false 14:01:08578 [INFO ] [veinternalprotocolZWaveController] - Connecting to serial port /dev/ttyACM0 14:01:08580 [INFO ] [bcoreserviceAbstractActiveService] - ZWave Refresh Service has been started 14:01:08591 [INFO ] [veinternalprotocolZWaveController] - Serial port is initialized 14:01:09612 [INFO ] [veinternalprotocolZWaveController] - Disconnected from serial port 14:01:09612 [INFO ] [veinternalprotocolZWaveController] - Stopped Z-Wave controller 14:01:12534 [INFO ] [bcoreserviceAbstractActiveService] - ZWave Refresh Service has been shut down 14:01:13581 [INFO ] [bcoreserviceAbstractActiveService] - ZWave Refresh Service has been shut down — Reply to this email directly or view it on GitHub.

[carpenike]

Sure. That used to get added to logback.xml, right? Where should I enable that now with OH2?

[cdjackson]

Same place but the files in a different location. From memory it's now in the runtime/etc folder or something similar... Otherwise the file format etc is the same as in the Zwave wiki

Sent from my iPhone

On 13 Jan 2016, at 20:13, Ryan Holt notifications@github.com wrote:

Sure. That used to get added to logback.xml, right? Where should I enable that now with OH2?

— Reply to this email directly or view it on GitHub.

[carpenike]

Ok. There isn't a logback.xml in the OH2 tree. I've copied the one from the OH1 install to the /opt/openhab/userdata/etc folder. Doesn't appear to be picking anything up though.

[_openhab@ha userdata]$ find /opt/openhab1 -name logback.xml
/opt/openhab1/configurations/logback.xml

[_openhab@ha userdata]$ find /opt/openhab/ -name logback.xml
[_openhab@ha userdata]$

[xsnrg]

The default logging now uses pax it seems. The config file is called org.ops4j.pax.logging.cfg and located in runtime/karaf/etc. Existing addons that use logback would still log I would think, just need to figure out where to put the config xml file so it picks it up ?

[carpenike]

Thanks. Flipped a couple "INFO"s to "DEBUG"s and it appears to spit out a bunch more.

Attached are the two logs.

OH2-ZWAVE-DebugLogs.zip

[xsnrg]

I changed the default level to DEBUG in mine through the karaf console (log:set DEBUG). It should have the same effect as jiggering the config file with non-permanent results.

When I did this, I noticed it changed the log level only for the karaf runtime, which makes sense I guess. We need to figure out how to pass DEBUG to the z-wave addon instead... Reading...

I am having the same issue when trying z-wave with 2.0 b1, adding it with the PaperUI interface.

[cdjackson]

Ok - it used to be there but everything changed with the introduction of karaf this week. I'll need to try and work out what's up :(

Sent from my iPhone

On 13 Jan 2016, at 19:33, Ryan Holt notifications@github.com wrote:

Ok. There isn't a logback.xml in the OH2 tree. I've copied the one from the OH1 install to the /opt/openhab/userdata/etc folder. Doesn't appear to be picking anything up though.

[_openhab@ha userdata]$ find /opt/openhab1 -name logback.xml /opt/openhab1/configurations/logback.xml

[_openhab@ha userdata]$ find /opt/openhab/ -name logback.xml [_openhab@ha userdata]$ — Reply to this email directly or view it on GitHub.

[cdjackson]

This should now be working again.

@carpenike where did you change the log level to get the debug logs?

[carpenike]

Changed it in the file xsnrg mentioned above. I don't think it actually increased the logging from the bindings though.

[cdjackson]

Kai has enlightened me -:

https://community.openhab.org/t/logging-under-oh2-karafa

:)

[carpenike]

Wow that log filtering is awesome. Still not working for me.

openhab>
log:set DEBUG org.openhab.binding.zwave
openhab> log:tail org.openhab.binding.zwave
14:23:06.362 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
14:23:06.387 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 1.9.0.201601170211
14:23:06.598 [DEBUG] [ng.zwave.internal.ZWaveActiveBinding] - ConverterHandler not initialised. Polling disabled.
14:23:06.604 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyACM0
14:23:06.605 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, healtime = 2
14:23:06.607 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, masterController = true
14:23:06.608 [DEBUG] [ng.zwave.internal.ZWaveActiveBinding] - Initialising zwave binding
14:23:06.665 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/command/*, service.pid=org.openhab.zwave, component.name=org.openhab.binding.zwave.activebinding, component.id=173, service.id=281, service.bundleid=166, service.scope=bundle} - org.openhab.binding.zwave
14:23:06.666 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.zwave.ZWaveBindingProvider}={component.name=org.openhab.binding.zwave.genericbindingprovider, component.id=174, service.id=279, service.bundleid=166, service.scope=bundle} - org.openhab.binding.zwave
14:23:06.690 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
14:23:06.866 [INFO ] [ve.internal.protocol.ZWaveController] - Starting Z-Wave controller
14:23:06.867 [INFO ] [ve.internal.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
14:23:06.869 [INFO ] [ve.internal.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
14:23:07.168 [DEBUG] [l.ZWaveController$ZWaveReceiveThread] - Starting Z-Wave thread: Receive
14:23:07.201 [INFO ] [ve.internal.protocol.ZWaveController] - Serial port is initialized
14:23:07.215 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Starting Z-Wave thread: Send
14:23:07.204 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting Z-Wave thread: Input
14:23:07.703 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.openhab.binding.zwave.internal.config.OpenHABConfigurationService}={service.id=294, service.bundleid=166, service.scope=singleton} - org.openhab.binding.zwave
14:23:07.709 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Stopped Z-Wave thread: Send
14:23:08.180 [DEBUG] [l.ZWaveController$ZWaveReceiveThread] - Stopped Z-Wave thread: Receive
14:23:08.187 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopped Z-Wave thread: Input
14:23:08.209 [INFO ] [ve.internal.protocol.ZWaveController] - Disconnected from serial port
14:23:08.214 [INFO ] [ve.internal.protocol.ZWaveController] - Stopped Z-Wave controller
14:23:10.209 [DEBUG] [ol.ZWaveController$WatchDogTimerTask] - Initialising network
14:23:10.244 [DEBUG] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00)
14:23:10.247 [DEBUG] [ve.internal.protocol.ZWaveController] - Enqueueing message. Queue length = 1
14:23:10.252 [DEBUG] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00)
14:23:10.255 [DEBUG] [ve.internal.protocol.ZWaveController] - Enqueueing message. Queue length = 2
14:23:10.260 [DEBUG] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00)
14:23:10.262 [DEBUG] [ve.internal.protocol.ZWaveController] - Enqueueing message. Queue length = 3
14:23:10.267 [DEBUG] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00)
14:23:10.270 [DEBUG] [ve.internal.protocol.ZWaveController] - Enqueueing message. Queue length = 4
14:23:10.275 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
14:23:10.279 [DEBUG] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00)
14:23:10.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Enqueueing message. Queue length = 5

[cdjackson]

Agreed - it’s still not fixed...

[carpenike]

Ah sorry. Just saw your comment above that it should be working again. https://github.com/cdjackson/HABmin2/issues/111#issuecomment-172388194

Also, does the issue also exist with your ZWave v2.0 source tree?

[cdjackson]

I’m not sure as I’ve not had the chance to run the v2 binding since Karaf was introduced…

On 18 Jan 2016, at 19:38, Ryan Holt notifications@github.com wrote:

Ah sorry. Just saw your comment above that it should be working again. #111 (comment) https://github.com/cdjackson/HABmin2/issues/111#issuecomment-172388194 Also, does the issue also exist with your ZWave v2.0 source tree?

— Reply to this email directly or view it on GitHub https://github.com/cdjackson/HABmin2/issues/111#issuecomment-172631249.

[carpenike]

OK. Is the source for v2 located here?

https://github.com/cdjackson/openhab2.git

if so mvn clean install has some errors that I can post on another thread if it's helpful.

[cdjackson]

Feel free - once I get this OH1 issue resolved I’ll look at v2 again… If you fancy fixing anything, then feel free to create a PR into my repo...

On 18 Jan 2016, at 19:42, Ryan Holt notifications@github.com wrote:

OK. Is the source for v2 located here?

https://github.com/cdjackson/openhab2.git https://github.com/cdjackson/openhab2.git if so mvn clean install has some errors that I can post on another thread if it's helpful.

— Reply to this email directly or view it on GitHub https://github.com/cdjackson/HABmin2/issues/111#issuecomment-172632194.

[cdjackson]

Potential fix for the OH1 zwave issue is here -: https://github.com/openhab/openhab/pull/3837

[carpenike]

Pulled the latest this morning from cloudbees and things are looking better. Getting this error at the start but at least it's polling my devices:

openhab> log:tail org.openhab.binding.zwave
09:55:16.520 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - ZWave 'updated' with null config
09:55:40.772 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyACM0
09:55:40.773 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, healtime = 2
09:55:40.776 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, masterController = true
09:55:40.804 [INFO ] [ve.internal.protocol.ZWaveController] - Starting Z-Wave controller
09:55:40.805 [INFO ] [ve.internal.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
09:55:40.806 [INFO ] [ve.internal.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
09:55:40.922 [INFO ] [ve.internal.protocol.ZWaveController] - Serial port is initialized
09:55:41.107 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyACM0
09:55:41.109 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, healtime = 2
09:55:41.110 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, masterController = true
09:55:41.115 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - InterruptedException during Z-Wave thread: sendQueue.take {}
java.lang.InterruptedException
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)[:1.8.0_65]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048)[:1.8.0_65]
        at java.util.concurrent.PriorityBlockingQueue.take(PriorityBlockingQueue.java:549)[:1.8.0_65]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveSendThread.run(ZWaveController.java:1240)[166:org.openhab.binding.zwave:1.9.0.201601190212]
09:55:41.940 [INFO ] [ve.internal.protocol.ZWaveController] - Disconnected from serial port
09:55:41.944 [INFO ] [ve.internal.protocol.ZWaveController] - Stopped Z-Wave controller
09:55:41.946 [INFO ] [ve.internal.protocol.ZWaveController] - Starting Z-Wave controller
09:55:41.947 [INFO ] [ve.internal.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
09:55:41.950 [INFO ] [ve.internal.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
09:55:41.963 [INFO ] [ve.internal.protocol.ZWaveController] - Serial port is initialized
09:55:41.970 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyACM0
09:55:41.971 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, healtime = 2
09:55:41.973 [INFO ] [ng.zwave.internal.ZWaveActiveBinding] - Update config, masterController = true
09:55:41.976 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - InterruptedException during Z-Wave thread: sendQueue.take {}
java.lang.InterruptedException
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)[:1.8.0_65]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048)[:1.8.0_65]
        at java.util.concurrent.PriorityBlockingQueue.take(PriorityBlockingQueue.java:549)[:1.8.0_65]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveSendThread.run(ZWaveController.java:1240)[166:org.openhab.binding.zwave:1.9.0.201601190212]
09:55:42.985 [INFO ] [ve.internal.protocol.ZWaveController] - Disconnected from serial port
09:55:42.986 [INFO ] [ve.internal.protocol.ZWaveController] - Stopped Z-Wave controller
09:55:42.987 [INFO ] [ve.internal.protocol.ZWaveController] - Starting Z-Wave controller
09:55:42.988 [INFO ] [ve.internal.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
09:55:42.988 [INFO ] [ve.internal.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
09:55:43.001 [INFO ] [ve.internal.protocol.ZWaveController] - Serial port is initialized
09:55:46.216 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
09:55:46.219 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
09:55:46.220 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
09:55:46.221 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
09:55:46.222 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
09:55:46.223 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
09:55:46.226 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 3
09:55:46.228 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------

Also having issues with the devices themselves but this is may not be related.

Do you know why I have this node 255 showing up? I only have 2 devices on my ZWave network at the moment. They were more stable / showed properly in HABMin on OH 1.8 as well.

09:56:08.989 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Node is DEAD. Dropping message.
09:56:09.115 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@7fc85509, ignoring.
09:56:09.184 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@5d5764de, ignoring.
09:56:09.237 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@5d5764de, ignoring.
09:56:09.280 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@5d5764de, ignoring.
09:56:09.353 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@7d40f55c, ignoring.
09:56:09.430 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@2b45bea4, ignoring.
09:56:09.625 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@72ba6a0f, ignoring.
09:56:09.789 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@28cbba9d, ignoring.
09:56:09.860 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@55544dd5, ignoring.
09:56:09.987 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = CONFIGURATION, value = org.openhab.binding.zwave.internal.protocol.ConfigurationParameter@55544dd5, ignoring.
09:56:10.274 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = SWITCH_MULTILEVEL, value = 0, ignoring.
09:56:10.324 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.325 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:10.326 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.377 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.377 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node location: null
09:56:10.379 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.431 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.432 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:10.432 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.575 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.577 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node location: null
09:56:10.578 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.629 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.631 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:10.632 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.683 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.683 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node location: null
09:56:10.684 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.735 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.736 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:10.737 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.788 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.788 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node location: null
09:56:10.789 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.841 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.841 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:10.842 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.893 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.894 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node location: null
09:56:10.895 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:10.946 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:10.948 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:10.949 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:11.000 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:11.000 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:11.001 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:11.054 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:11.054 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node name: null
09:56:11.055 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:11.178 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:11.179 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node location: null
09:56:11.180 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:11.182 [ERROR] [nitialization.ZWaveNodeStageAdvancer] - NODE 2: Node advancer: Retries exceeded at DYNAMIC_VALUES
09:56:12.528 [ERROR] [andclass.ZWaveNodeNamingCommandClass] - NODE 2 : Node Name report error in message length
09:56:12.529 [INFO ] [andclass.ZWaveNodeNamingCommandClass] - NODE 2: Node location: null
09:56:12.530 [WARN ] [ng.zwave.internal.ZWaveActiveBinding] - NODE 2: No item bound for event, endpoint = 0, command class = NODE_NAMING, value = null, ignoring.
09:56:15.365 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Node is DEAD. Dropping message.
09:56:26.319 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 3: Node is DEAD. Dropping message.
09:57:07.010 [ERROR] [essage.ApplicationUpdateMessageClass] - NODE 255: Got Node Info Request Failed. Requeueing
09:57:07.717 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
09:57:11.854 [ERROR] [essage.ApplicationUpdateMessageClass] - NODE 255: Got Node Info Request Failed. Requeueing
09:57:12.720 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 03
09:57:16.828 [WARN ] [essage.ApplicationUpdateMessageClass] - NODE 255: Node Info Request Failed 3x. Discarding message: Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 03
09:57:17.723 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 03
09:57:21.846 [WARN ] [essage.ApplicationUpdateMessageClass] - NODE 255: Node Info Request Failed 3x. Discarding message: Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 03
09:57:22.726 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 03

[cdjackson]

The error is the one that we see that caused the whole problem associated with startup - the binding should restart the COM port connection now (which it did) but it's interesting that the issue might still occur occasionally (FYI @kaikreuzer - I might update the other services to also start immediately to see if this helps, but I'm still unclear why there's this semaphore interrupt issue).

Do you know why I have this node 255 showing up?

Yes - this is the controller :)

[carpenike]

Ahh makes sense. :) Was that Node 0 in OH1?

[cdjackson]

No - it's always been node 255 (and this binding is still the OH1 binding - you're just running under OH2, but it's the same). The controller though has a dual personality in that it also has another ID (normally node 1). This is the controllers node for communicating with other devices, and node 255 is the node used for commands sent from OH...

Node 0 doesn't exist.

[carpenike]

Gotcha. That's what I remember seeing -- 1 in HABmin.

Thanks again for the help. No pressure -- Is HABmin2 ready for testing yet on OH2/Karaf?

[cdjackson]

Yes - I think HABmin2 should work ok under Karaf - I did a quick test the other night so I think it’s now ok…

On 19 Jan 2016, at 15:55, Ryan Holt notifications@github.com wrote:

Gotcha. That's what I remember seeing -- 1 in HABmin.

Thanks again for the help. No pressure -- Is HABmin2 ready for testing yet on OH2/Karaf?

— Reply to this email directly or view it on GitHub https://github.com/cdjackson/HABmin2/issues/111#issuecomment-172896820.

[carpenike]

Sounds good. I'll give it a try.

Still require HABmin1 to be installed?

[cdjackson]

HABmin 1 won’t work on OH2 due to the way the web side it handled…

On 19 Jan 2016, at 18:30, Ryan Holt notifications@github.com wrote:

Sounds good. I'll give it a try.

Still require HABmin1 to be installed?

— Reply to this email directly or view it on GitHub https://github.com/cdjackson/HABmin2/issues/111#issuecomment-172943349.

[carpenike]

Right. There just used to be a requirement to have the HABmin1 jar file installed on the OH2 system in order to get HABmin2 to load wasn’t there?

From: Chris Jackson [mailto:notifications@github.com] Sent: Tuesday, January 19, 2016 3:24 PM To: cdjackson/HABmin2 HABmin2@noreply.github.com Cc: Ryan Holt ryan@ryanholt.net Subject: Re: [HABmin2] Z-Wave Shutting Down -- OH2 B1 (#111)

HABmin 1 won’t work on OH2 due to the way the web side it handled…

On 19 Jan 2016, at 18:30, Ryan Holt notifications@github.com<mailto:notifications@github.com> wrote:

Sounds good. I'll give it a try.

Still require HABmin1 to be installed?

— Reply to this email directly or view it on GitHub https://github.com/cdjackson/HABmin2/issues/111#issuecomment-172943349.

— Reply to this email directly or view it on GitHubhttps://github.com/cdjackson/HABmin2/issues/111#issuecomment-172975114.

[cdjackson]

On 19 Jan 2016, at 20:25, Ryan Holt notifications@github.com wrote:

Right. There just used to be a requirement to have the HABmin1 jar file installed on the OH2 system in order to get HABmin2 to load wasn’t there?

No - there was (IS with the current version) the requirement to have the OH1 ZWAVE binding installed - not the OH1 HABmin binding...

[carpenike]

Got it – thanks.

From: Chris Jackson [mailto:notifications@github.com] Sent: Tuesday, January 19, 2016 3:46 PM To: cdjackson/HABmin2 HABmin2@noreply.github.com Cc: Ryan Holt ryan@ryanholt.net Subject: Re: [HABmin2] Z-Wave Shutting Down -- OH2 B1 (#111)

On 19 Jan 2016, at 20:25, Ryan Holt notifications@github.com<mailto:notifications@github.com> wrote:

Right. There just used to be a requirement to have the HABmin1 jar file installed on the OH2 system in order to get HABmin2 to load wasn’t there?

No - there was (IS with the current version) the requirement to have the OH1 ZWAVE binding installed - not the OH1 HABmin binding...

— Reply to this email directly or view it on GitHubhttps://github.com/cdjackson/HABmin2/issues/111#issuecomment-172981366.

[cdjackson]

The ZWave startup issue under OH2 is now resolved... https://github.com/openhab/openhab/pull/3837