I thought I’d start a new post on getting started with the OH2 Z-Wave binding since the other test thread is way too long to find anything now!
I’ve put together a short ‘how to’ here. It provides a quick overview of how to start up the binding and link channels to items.
If there’s any questions directly related to getting started with Z-Wave, then please ask them here.
Hi Chris, thanks for your help! I guess I’ll post this here. Not sure if it’s more related to the zwave binding or to issues with my CT30, but I don’t know how to interpret the logs.
I just installed a CT30 thermostat with the z-wave U-SNAP module. Trying to get this set up in my fresh openHAB2 install, mostly using Habmin2. I already have an Aeotec Multisensor 6 included and working. With that sensor I wasn’t having success initiating discovery/inclusion from Habmin2 (it linked ok but then appeared in the inbox as an unknown device). When I followed Aeotec’s instructions by disconnecting the Z-Stick (after shutting down openhab2 of course), bringing it over to the sensor, and pressing the button on both the stick and the sensor, it worked. Restarting OH2, there it was in the inbox, properly recognized.
So with the CT30 I tried the same thing–shut down OH2, bring the stick over, set both to inclusion. The CT30 indicates a successful link. I insert the stick back into the computer and start up OH2. The stick reports the new device, which is Node #4, but there are problems:
(In the following, Node 1 is the stick, Node 2 is dead because I screwed up and didn’t exclude the multisensor correctly before resetting it and trying again, Node 3 is the multisensor, and Node 4 is the CT30. I removed the noisy lines with the frame counters changing etc.)
2016-06-05 13:44:03.575 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2016-06-05 13:44:03.578 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2016-06-05 13:44:03.579 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2016-06-05 13:44:03.580 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2016-06-05 13:44:03.581 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2016-06-05 13:44:03.582 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2016-06-05 13:44:03.583 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2016-06-05 13:44:03.584 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 4
2016-06-05 13:44:03.584 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2016-06-05 13:44:03.638 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node...
2016-06-05 13:44:03.640 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:57525fc0' changed from OFFLINE to ONLINE
2016-06-05 13:44:03.656 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
2016-06-05 13:44:04.507 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from OFFLINE to ONLINE: PROTOINFO
2016-06-05 13:44:04.636 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from ONLINE: PROTOINFO to ONLINE: INIT_NEIGHBORS
2016-06-05 13:44:04.851 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from ONLINE: INIT_NEIGHBORS to ONLINE: DISCOVERY_COMPLETE
2016-06-05 13:44:04.857 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing 'zwave:device:57525fc0:node3' has been updated.
2016-06-05 13:44:04.867 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from ONLINE: DISCOVERY_COMPLETE to ONLINE: PROTOINFO
2016-06-05 13:44:04.875 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from ONLINE: PROTOINFO to ONLINE: INIT_NEIGHBORS
2016-06-05 13:44:04.892 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from ONLINE: INIT_NEIGHBORS to ONLINE: FAILED_CHECK
2016-06-05 13:44:04.906 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from ONLINE: FAILED_CHECK to ONLINE: WAIT
2016-06-05 13:44:04.911 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:57525fc0:node3' changed from ONLINE: WAIT to ONLINE: PING
2016-06-05 13:44:09.072 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-05 13:44:13.202 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-05 13:44:17.303 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Node is DEAD. Dropping message.
2016-06-05 13:44:19.355 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device could not be resolved to a thingType! 0098:0001:001E::4.9
2016-06-05 13:44:19.453 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:57525fc0:node4' to inbox.
2016-06-05 13:44:19.455 [INFO ] [smarthome.event.InboxAddedEvent ] - Discovery Result with UID 'zwave:device:57525fc0:node4' has been added.
2016-06-05 13:44:21.121 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node advancer: GET_CONFIGURATION - CONFIGURATION class not supported
2016-06-05 13:44:25.791 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data was not placed on stack due to error 0.
2016-06-05 13:44:27.009 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 31 05 01 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 31 05 01 (6)
2016-06-05 13:44:27.021 [INFO ] [marthome.event.ItemStateChangedEvent] - [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 31 05 01 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 31 05 01 (6)
2016-06-05 13:44:30.788 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-05 13:44:30.792 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message.
2016-06-05 13:44:32.324 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node advancer: Retries exceeded at DYNAMIC_VALUES
In Habmin2 the CT30 appears in the inbox as “Z-Wave Node 4 (0098:0001:001E:4.9)”.
The firmware on my unit is pretty old… I’ve seen talk about issues with zwave USNAP v7.4, but mine claims to be v4.99! Main unit v1.92. Upgrading to a newer RTZW-01 or even an RTZW-02 USNAP module would be reasonable, after I understand why this one isn’t working. It’s mains powered, so battery saving isn’t a big deal.
At the moment the CT30 isn’t in the OH2 database - I’ll update the binding to add this shortly (tonight or tomorrow). Once this is included, let’s pick up any other issues then 
Sweet. I’ll give it another whirl this weekend. Happy to help test whatever.
With the updated database, my CT30 is now recognized. Thanks!
OH2 is not happy, though. The log contains many timeouts and dire-sounding errors. There are some periodic reports from the thermostat for a couple of hours, then the node gets marked as dead. Here’s the relevant section of the log, starting from system init after I’ve included the CT30 into the network. (Inclusion was performed using the Z-Stick action button, disconnected from USB.) The CT30 is Node 2 and there are no other Z-Wave devices in the network yet.
2016-06-11 00:21:10.442 [INFO ] [smarthome.event.ThingAddedEvent ] - Thing 'zwave:serial_zstick:f3f77978' has been added.
2016-06-11 00:21:10.500 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:f3f77978' changed from UNINITIALIZED to INITIALIZING
2016-06-11 00:21:10.597 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_f3f77978_serial_sof' has been added.
2016-06-11 00:21:10.600 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_f3f77978_serial_sof-zwave:serial_zstick:f3f77978:serial_sof' has been added.
2016-06-11 00:21:10.680 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2016-06-11 00:21:10.683 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing 'zwave:serial_zstick:f3f77978' has been updated.
2016-06-11 00:21:10.688 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:f3f77978' changed from INITIALIZING to OFFLINE
2016-06-11 00:21:10.714 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2016-06-11 00:21:10.743 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_f3f77978_serial_ack' has been added.
2016-06-11 00:21:10.746 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2016-06-11 00:21:10.746 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_f3f77978_serial_ack-zwave:serial_zstick:f3f77978:serial_ack' has been added.
2016-06-11 00:21:10.789 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2016-06-11 00:21:10.791 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2016-06-11 00:21:10.828 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_f3f77978_serial_nak' has been added.
2016-06-11 00:21:10.834 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_f3f77978_serial_nak-zwave:serial_zstick:f3f77978:serial_nak' has been added.
2016-06-11 00:21:10.904 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_f3f77978_serial_can' has been added.
2016-06-11 00:21:10.906 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_f3f77978_serial_can-zwave:serial_zstick:f3f77978:serial_can' has been added.
2016-06-11 00:21:10.981 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_f3f77978_serial_oof' has been added.
2016-06-11 00:21:10.983 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_f3f77978_serial_oof-zwave:serial_zstick:f3f77978:serial_oof' has been added.
2016-06-11 00:21:11.362 [ERROR] [ve.internal.protocol.ZWaveController] - Neither inclusion nor exclusion was active!
2016-06-11 00:21:14.036 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2016-06-11 00:21:14.038 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2016-06-11 00:21:14.040 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2016-06-11 00:21:14.041 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2016-06-11 00:21:14.042 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2016-06-11 00:21:14.044 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2016-06-11 00:21:14.045 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2016-06-11 00:21:14.070 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:f3f77978' changed from OFFLINE to ONLINE
2016-06-11 00:21:14.684 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Restore from config: Error. Data invalid, ignoring config.
2016-06-11 00:21:19.053 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-11 00:21:24.058 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2016-06-11 00:21:29.062 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2016-06-11 00:21:34.066 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=EnableSuc[0x52], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01
2016-06-11 00:21:39.069 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-11 00:21:44.073 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2016-06-11 00:21:49.076 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2016-06-11 00:21:54.081 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=SetSucNodeID[0x54], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 01 01
2016-06-11 00:21:59.381 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
2016-06-11 00:21:59.385 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-11 00:22:00.394 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:f3f77978:node2' to inbox.
2016-06-11 00:22:00.395 [INFO ] [smarthome.event.InboxAddedEvent ] - Discovery Result with UID 'zwave:device:f3f77978:node2' has been added.
2016-06-11 00:22:01.933 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - CONFIGURATION class not supported
2016-06-11 00:22:07.678 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Retries exceeded at DYNAMIC_VALUES
2016-06-11 00:23:25.231 [INFO ] [smarthome.event.InboxRemovedEvent ] - Discovery Result with UID 'zwave:device:f3f77978:node2' has been removed.
2016-06-11 00:23:25.235 [INFO ] [smarthome.event.ThingAddedEvent ] - Thing 'zwave:device:f3f77978:node2' has been added.
2016-06-11 00:23:25.294 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from UNINITIALIZED to INITIALIZING
2016-06-11 00:23:25.320 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from INITIALIZING to OFFLINE
2016-06-11 00:23:25.329 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from OFFLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
2016-06-11 00:23:25.330 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
2016-06-11 00:23:25.334 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to ONLINE
2016-06-11 00:23:25.523 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from ONLINE to INITIALIZING
2016-06-11 00:23:25.530 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from INITIALIZING to OFFLINE
2016-06-11 00:23:25.540 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
2016-06-11 00:23:25.541 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
2016-06-11 00:23:25.542 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from OFFLINE to ONLINE
2016-06-11 00:23:25.559 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing 'zwave:device:f3f77978:node2' has been updated.
2016-06-11 00:23:25.663 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_battery_level' has been added.
2016-06-11 00:23:25.670 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_battery_level-zwave:device:f3f77978:node2:battery-level' has been added.
2016-06-11 00:23:25.756 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_thermostat_state' has been added.
2016-06-11 00:23:25.764 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_thermostat_state-zwave:device:f3f77978:node2:thermostat_state' has been added.
2016-06-11 00:23:25.838 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_sensor_temperature' has been added.
2016-06-11 00:23:25.842 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_sensor_temperature-zwave:device:f3f77978:node2:sensor_temperature' has been added.
2016-06-11 00:23:25.921 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_thermostat_mode' has been added.
2016-06-11 00:23:25.923 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_thermostat_mode-zwave:device:f3f77978:node2:thermostat_mode' has been added.
2016-06-11 00:23:25.999 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_thermostat_fanmode' has been added.
2016-06-11 00:23:26.003 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_thermostat_fanmode-zwave:device:f3f77978:node2:thermostat_fanmode' has been added.
2016-06-11 00:23:26.085 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_time_offset' has been added.
2016-06-11 00:23:26.088 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_time_offset-zwave:device:f3f77978:node2:time_offset' has been added.
2016-06-11 00:23:26.168 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_thermostat_setpoint_cooling' has been added.
2016-06-11 00:23:26.171 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_thermostat_setpoint_cooling-zwave:device:f3f77978:node2:thermostat_setpoint_cooling' has been added.
2016-06-11 00:23:26.250 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_f3f77978_node2_thermostat_setpoint_heating' has been added.
2016-06-11 00:23:26.253 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_f3f77978_node2_thermostat_setpoint_heating-zwave:device:f3f77978:node2:thermostat_setpoint_heating' has been added.
2016-06-11 00:25:35.215 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Error getting configurationCommandClass
2016-06-11 00:25:35.318 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing 'zwave:device:f3f77978:node2' has been updated.
2016-06-11 00:25:35.391 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing 'zwave:device:f3f77978:node2' has been updated.
2016-06-11 00:25:35.410 [INFO ] [marthome.event.ConfigStatusInfoEvent] - org.eclipse.smarthome.config.core.status.events.ConfigStatusInfoEvent@51f48c
2016-06-11 00:33:29.176 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
2016-06-11 00:33:29.177 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from ONLINE to OFFLINE
2016-06-11 00:33:29.193 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from OFFLINE to ONLINE
2016-06-11 00:33:29.206 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing 'zwave:device:f3f77978:node2' has been updated.
2016-06-11 00:34:08.226 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Error getting configurationCommandClass
2016-06-11 00:34:08.349 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing 'zwave:device:f3f77978:node2' has been updated.
2016-06-11 00:34:08.353 [INFO ] [marthome.event.ConfigStatusInfoEvent] - org.eclipse.smarthome.config.core.status.events.ConfigStatusInfoEvent@f7ac79
2016-06-11 00:53:25.343 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:351)[201:org.openhab.binding.zwave:2.0.0.201606110103]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_91]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_91]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
2016-06-11 01:03:31.151 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_thermostat_state changed from NULL to 0
2016-06-11 01:03:31.261 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_sensor_temperature changed from NULL to 66.5
2016-06-11 01:03:31.315 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data was not placed on stack due to error 0.
2016-06-11 01:03:33.211 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 31 05 01 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 03 31 05 01 (6)
2016-06-11 01:03:36.303 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-11 01:03:36.306 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-11 01:03:37.064 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_thermostat_fanmode changed from NULL to 0
2016-06-11 01:03:37.610 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_thermostat_setpoint_heating changed from NULL to 62
2016-06-11 01:23:25.338 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:351)[201:org.openhab.binding.zwave:2.0.0.201606110103]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_91]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_91]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
2016-06-11 01:33:33.111 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_thermostat_mode changed from NULL to 0
2016-06-11 01:33:34.042 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_sensor_temperature changed from 66.5 to 66
2016-06-11 01:53:25.339 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:351)[201:org.openhab.binding.zwave:2.0.0.201606110103]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_91]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_91]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
2016-06-11 02:03:31.708 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_sensor_temperature changed from 66 to 65.5
2016-06-11 02:03:31.780 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2016-06-11 02:03:31.783 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 2: Already processed another send data request for this callback Id, ignoring.
2016-06-11 02:03:31.895 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 2: Already processed another send data request for this callback Id, ignoring.
2016-06-11 02:03:36.778 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-11 02:03:36.780 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-11 02:23:25.339 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:351)[201:org.openhab.binding.zwave:2.0.0.201606110103]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_91]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_91]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
2016-06-11 02:33:32.549 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2016-06-11 02:33:37.548 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-11 02:33:37.549 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-11 02:33:38.849 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_thermostat_setpoint_cooling changed from NULL to 85
2016-06-11 02:53:25.339 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:351)[201:org.openhab.binding.zwave:2.0.0.201606110103]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_91]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_91]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
2016-06-11 03:03:31.249 [INFO ] [marthome.event.ItemStateChangedEvent] - zwave_device_f3f77978_node2_sensor_temperature changed from 65.5 to 65
2016-06-11 03:03:31.319 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data was not placed on stack due to error 0.
2016-06-11 03:03:36.312 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-11 03:03:36.314 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-11 03:23:25.339 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
So the CT30 is sending updates (or being polled?) every 30 minutes, but the communication is flaky. (Over the air, or over the Z-Stick serial link?) Not sure if the null-pointer exception is related, as it happens at different times, although also every 30 minutes.
This pattern holds for another hour, at which point OH2 (or the stick?) gives up altogether:
2016-06-11 04:03:33.075 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2016-06-11 04:03:38.062 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-11 04:03:38.065 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-11 04:03:43.070 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
2016-06-11 04:03:43.072 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-06-11 04:03:45.182 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Node is DEAD. Dropping message.
2016-06-11 04:03:45.185 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:f3f77978:node2' changed from ONLINE to OFFLINE
2016-06-11 04:03:49.904 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Node is DEAD. Dropping message.
2016-06-11 04:03:54.538 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Node is DEAD. Dropping message.
2016-06-11 04:03:55.688 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Node is DEAD. Dropping message.
This sequence then repeats indefinitely, every 30 minutes.
My Z-Stick is the new Gen5 version (white), and it’s located less than two meters from the thermostat, so I wouldn’t expect signal levels to be a problem.
I also noticed couple more issues which may or may not be related:
I’ve tried starting inclusion/discovery from within Paper UI or Habmin2 on a couple of different occasions now, once with the CT30 and once with my Aeotec Multisensor 6. In both cases the inclusion “succeeded” but the resulting device was a zombie (for lack of a better word). The nodes believe they are linked, and they show up in the inbox, but they are not recognized correctly–they remain as a generic number instead of a “Multisensor 6” or “Thermostat”. The only reliable way of including devices so far has been to remove the stick and use its action button to link, then reconnect and restart OH2 and let the binding discover the nodes already in the stick’s memory. Sorry I don’t have a relevant section of the log to show… it’s lost somewhere in the 10 MB file.
OH2 seems to be stepping on itself during some serial-port operations. I get a lot of sequences like the following:
2016-06-04 20:50:23.364 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0’
2016-06-04 20:50:23.439 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2016-06-04 20:50:23.443 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2016-06-04 20:50:23.445 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2016-06-04 20:50:23.447 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2016-06-04 20:50:23.449 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 1
2016-06-04 20:50:23.451 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2016-06-04 20:50:23.473 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:serial_zstick:57525fc0’ changed from OFFLINE to ONLINE
2016-06-04 20:50:25.369 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:serial_zstick:57525fc0’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Serial Error: Port /dev/ttyACM0 in use
I often notice this upon first launching OH2. A solution is to delete and then re-add the z-stick thing.
Are these logs useful? I could increase the debug level to order if necessary, and maybe post a larger chunk on pastebin or something.
Thanks for your help!
Thanks.
I would suspect there are a few issues here - they may be related, or not…
Firstly, there is an issue with including nodes and the new node not being properly discovered. This is a two stage process, and it seems sometimes the second stage doesn’t update some information in the inbox. I’m not sure why this is, or if the bug is in the binding or ESH. I’ve tried to replicate this, but haven’t so far. This is not an uncommon problem and I need to work out how to solve this. I think this will fix a number of the issues you see (such as the NPE during polling).
The DEAD issue is probably unrelated, and might well indicate that the stick can’t communicate well with the CT30.
Regarding the COM port issue - can you check in the console (with the list command) that you don’t have two copies of the binding running or something - I’ve certainly never seen such issues with opening the port.
I’ll check again next time I see this, but I usually have “top” running in a window so I can make sure the java process has exited before restarting OH2. It is tempting to wonder if this has the same root cause as the apparent difficulty the binding has in talking to the Z-Stick, and once a solution is found, my other problem (dead node) would go away too. If only.
Is it normal to find Z-Wave devices that don’t get along with a particular controller? Would it be worth swapping out the thermostat’s Z-Wave “usnap” module with a newer one? Supposedly there is a RTZW-02 (most everyone has RTZW-01) with the newer Sigma chipset. It would really help if I knew someone else had this working with OH. Remote-controlling my thermostat was kind of the main point of this foray into home-automation…
No - since most controllers run reasonably standard firmware from Sigma, it normally doesn’t matter what controller is used. The more common thing is ‘crappy’ implementations within the device, but we can normally work around these in the binding.
@xsnrg are you using the CT30, or just the CT100 (I don’t know what the difference is).
Just the CT-100s here. I have a contact at radiothermostat.com now that I am trying to wrangle more data from, including what ever other devices they are willing to give data for. I don’t believe my CT-100s are complete yet either. I know they have a clock on them that can be set remotely for example, and probably other things.
In the meantime, he did give me a link for the CT-110 and said it is mostly similar. http://products.z-wavealliance.org/products/1333/. This does have more data than I was able to find for the CT-100, so that is something.
Similarly, the CT32 has more info than the CT30: http://products.z-wavealliance.org/products/1046
Does the XML file show the CLOCK class? It’s not in the database, but it should be supported if the device reports it.
sure does.
<clockCommandClass>
<version>1</version>
<instances>1</instances>
<versionSupported>1</versionSupported>
</clockCommandClass>
I know the clock stuff was worked on after the device was created in the DB, do I need to send along a new XML to the DB?
The database won’t allow another upload (I might change that, but at the moment it won’t allow a second XML upload to try and avoid ‘screw-ups’).
However, we probably should add it - I’ll take a look tomorrow unless you fancy adding this command class. It should have channel type time_offset.
Is the CT30 working with Zwave in OpenHAB2 now? - I have looked at lots of threads but no definitive answer. I have seen that they are available at a reasonable price and I am pretty sure if it works with OpenHAB2 it will suit my needs. I just wanted to get a definitive, “it works using Zwave” or not.
I did note that there is a WiFi binding for it but the WiFi module is not my favored approach.
UPDATE: OK it’s early days yet but I can confirm that the CT30 is working with the zwave binding in openHAB2. It needed a lot of coaxing but eventually it is working pretty well. I have successfully implemented rules that are controlling the CT30 thermostat in the way I wanted it to.