Skip to content
This repository has been archived by the owner on May 23, 2019. It is now read-only.

Z-Wave Shutting Down -- OH2 B1 #111

Closed
carpenike opened this issue Jan 13, 2016 · 30 comments
Closed

Z-Wave Shutting Down -- OH2 B1 #111

carpenike opened this issue Jan 13, 2016 · 30 comments

Comments

@carpenike
Copy link

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

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

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

@cdjackson
Copy link
Contributor

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

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

xsnrg commented Jan 13, 2016

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

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

xsnrg commented Jan 13, 2016

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

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

This should now be working again.

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

@carpenike
Copy link
Author

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

@cdjackson
Copy link
Contributor

cdjackson commented Jan 17, 2016 via email

@carpenike
Copy link
Author

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

Agreed - it’s still not fixed...

@carpenike
Copy link
Author

Ah sorry. Just saw your comment above that it should be working again. #111 (comment)

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

@cdjackson
Copy link
Contributor

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) #111 (comment)
Also, does the issue also exist with your ZWave v2.0 source tree?


Reply to this email directly or view it on GitHub #111 (comment).

@carpenike
Copy link
Author

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

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 #111 (comment).

@cdjackson
Copy link
Contributor

Potential fix for the OH1 zwave issue is here -: openhab/openhab1-addons#3837

@carpenike
Copy link
Author

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

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

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

@cdjackson
Copy link
Contributor

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

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

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 #111 (comment).

@carpenike
Copy link
Author

Sounds good. I'll give it a try.

Still require HABmin1 to be installed?

@cdjackson
Copy link
Contributor

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 #111 (comment).

@carpenike
Copy link
Author

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.commailto: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 #111 (comment).


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

@cdjackson
Copy link
Contributor

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

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.commailto: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//issues/111#issuecomment-172981366.

@cdjackson
Copy link
Contributor

The ZWave startup issue under OH2 is now resolved...
openhab/openhab1-addons#3837

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

No branches or pull requests

3 participants