OpenHAB won't recognise zwave dongle

picarsqu3 · December 5, 2015, 1:13pm

Check out the part of the Wiki that explains how to modify your logback.xml - I think you will want to put your z-wave into it’s own log and set it to Trace. This may give you some better idea of what is happening.

jsable · December 5, 2015, 2:15pm

I have had that already set up for quite a while, but I don’t know how to change it to set it to trace, and couldn’t find an example of it… Is there a document or wiki to tell me how to interpret what this all means? Here is the 1st half from my zwave.log file:

2015-12-05 08:36:10.864 [DEBUG] [.zwave.internal.ZWaveActivator:36  ]- Z-Wave binding started. Version 1.7.1
2015-12-05 08:36:10.985 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled.
2015-12-05 08:36:11.021 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = /dev/ttyUSB0
2015-12-05 08:36:11.021 [INFO ] [.z.internal.ZWaveActiveBinding:330 ]- Update config, healtime = 2
2015-12-05 08:36:11.028 [INFO ] [.z.internal.ZWaveActiveBinding:375 ]- Update config, setSUC = false
2015-12-05 08:36:11.029 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = false
2015-12-05 08:36:11.029 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = true
2015-12-05 08:36:11.029 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding
2015-12-05 08:36:11.320 [INFO ] [b.z.i.protocol.ZWaveController:146 ]- Starting Z-Wave controller
2015-12-05 08:36:11.321 [INFO ] [b.z.i.protocol.ZWaveController:154 ]- Z-Wave timeout is set to 5000ms. Soft reset is false.
2015-12-05 08:36:11.321 [INFO ] [b.z.i.protocol.ZWaveController:407 ]- Connecting to serial port /dev/ttyUSB0
2015-12-05 08:36:12.242 [DEBUG] [eController$ZWaveReceiveThread:1460]- Starting Z-Wave thread: Receive
2015-12-05 08:36:12.244 [INFO ] [b.z.i.protocol.ZWaveController:427 ]- Serial port is initialized
2015-12-05 08:36:12.245 [DEBUG] [WaveController$ZWaveSendThread:1244]- Starting Z-Wave thread: Send
2015-12-05 08:36:12.244 [DEBUG] [b.z.i.protocol.ZWaveController:1201]- Starting Z-Wave thread: Input
2015-12-05 08:36:15.249 [DEBUG] [veController$WatchDogTimerTask:176 ]- Initialising network
2015-12-05 08:36:15.274 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00)
2015-12-05 08:36:15.276 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:36:15.278 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:36:15.279 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:36:15.276 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 0
2015-12-05 08:36:15.328 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00)
2015-12-05 08:36:15.329 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:36:15.352 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00)
2015-12-05 08:36:15.354 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:36:15.357 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00)
2015-12-05 08:36:15.358 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:36:15.360 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30  ]- Get SUC NodeID
2015-12-05 08:36:15.368 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00)
2015-12-05 08:36:15.369 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:36:16.097 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:36:20.305 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:36:20.305 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 08:36:20.306 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 08:36:20.308 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:36:20.309 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:36:21.118 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:36:25.314 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:36:25.315 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 08:36:25.315 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 08:36:25.316 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:36:25.317 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:36:26.120 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:36:30.325 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:36:30.326 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 08:36:30.326 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 08:36:30.328 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:36:30.330 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:36:31.122 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:36:35.474 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = GetVersion (0x15), type = Request (0x00), payload = 
2015-12-05 08:36:35.475 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:36:35.476 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:36:35.477 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:36:36.131 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:36:40.837 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:36:40.837 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:36:40.837 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:36:40.838 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:36:40.839 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:36:41.133 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:36:45.846 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:36:45.847 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:36:45.847 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:36:45.848 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:36:45.849 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:36:46.141 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:36:50.852 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:36:50.853 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:36:50.854 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:36:50.855 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:36:50.856 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:36:51.142 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:36:55.863 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = MemoryGetId (0x20), type = Request (0x00), payload = 
2015-12-05 08:36:55.864 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:36:55.865 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:36:55.866 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:36:56.144 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:37:00.871 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:37:00.872 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:37:00.874 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:37:00.876 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:37:00.876 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:37:01.145 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:37:05.880 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:37:05.881 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:37:05.883 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:37:05.885 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:37:05.888 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:37:06.147 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:37:10.895 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:37:10.897 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:37:10.898 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:37:10.899 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:37:10.900 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:37:11.149 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:37:15.907 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = 
2015-12-05 08:37:15.908 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:37:15.909 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:37:15.910 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:37:20.945 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:37:20.946 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:37:20.946 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:37:20.948 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:37:20.948 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:37:25.952 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:37:25.953 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:37:25.954 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:37:25.955 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:37:25.956 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:37:30.974 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:37:30.975 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:37:30.976 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:37:30.977 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:37:30.978 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:37:35.985 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F

jsable · December 5, 2015, 2:15pm

Part 2 of my zwave.log file:

2015-12-05 08:37:35.985 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:37:35.985 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:37:35.986 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:37:40.996 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:37:40.997 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:37:40.997 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:37:40.998 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:37:41.001 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:37:46.013 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:37:46.015 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:37:46.016 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:37:46.017 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:37:46.024 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:37:51.047 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:37:51.048 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:37:51.048 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:37:51.049 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:37:51.049 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:37:56.054 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = 
2015-12-05 08:44:57.108 [DEBUG] [.zwave.internal.ZWaveActivator:36  ]- Z-Wave binding started. Version 1.7.1
2015-12-05 08:44:57.271 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled.
2015-12-05 08:44:58.354 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = /dev/ttyUSB0
2015-12-05 08:44:58.355 [INFO ] [.z.internal.ZWaveActiveBinding:330 ]- Update config, healtime = 2
2015-12-05 08:44:58.356 [INFO ] [.z.internal.ZWaveActiveBinding:375 ]- Update config, setSUC = false
2015-12-05 08:44:58.392 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = false
2015-12-05 08:44:58.401 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = true
2015-12-05 08:44:58.402 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding
2015-12-05 08:44:58.800 [INFO ] [b.z.i.protocol.ZWaveController:146 ]- Starting Z-Wave controller
2015-12-05 08:44:58.804 [INFO ] [b.z.i.protocol.ZWaveController:154 ]- Z-Wave timeout is set to 5000ms. Soft reset is false.
2015-12-05 08:44:58.811 [INFO ] [b.z.i.protocol.ZWaveController:407 ]- Connecting to serial port /dev/ttyUSB0
2015-12-05 08:45:00.103 [DEBUG] [eController$ZWaveReceiveThread:1460]- Starting Z-Wave thread: Receive
2015-12-05 08:45:00.197 [DEBUG] [b.z.i.protocol.ZWaveController:1201]- Starting Z-Wave thread: Input
2015-12-05 08:45:00.199 [INFO ] [b.z.i.protocol.ZWaveController:427 ]- Serial port is initialized
2015-12-05 08:45:00.209 [DEBUG] [WaveController$ZWaveSendThread:1244]- Starting Z-Wave thread: Send
2015-12-05 08:45:03.214 [DEBUG] [veController$WatchDogTimerTask:176 ]- Initialising network
2015-12-05 08:45:03.260 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00)
2015-12-05 08:45:03.261 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:45:03.263 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:45:03.265 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:45:03.270 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 0
2015-12-05 08:45:03.273 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00)
2015-12-05 08:45:03.274 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:45:03.280 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00)
2015-12-05 08:45:03.288 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:45:03.294 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00)
2015-12-05 08:45:03.295 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:45:03.297 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30  ]- Get SUC NodeID
2015-12-05 08:45:03.299 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00)
2015-12-05 08:45:03.299 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:45:03.478 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:45:08.282 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:45:08.283 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 08:45:08.283 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 08:45:08.285 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:45:08.286 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:45:08.479 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:45:13.294 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:45:13.295 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 08:45:13.295 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 08:45:13.296 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:45:13.297 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:45:13.484 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:45:18.484 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:45:18.610 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:45:18.610 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 08:45:18.611 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 08:45:18.611 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 08:45:18.612 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 08:45:23.491 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 08:45:23.622 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = GetVersion (0x15), type = Request (0x00), payload = 
2015-12-05 08:45:23.623 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:45:23.630 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:45:23.641 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:45:28.492 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:45:28.670 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:45:28.671 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:45:28.672 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:45:28.674 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:45:28.685 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:45:33.499 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:45:33.692 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:45:33.692 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:45:33.693 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:45:33.693 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:45:33.694 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:45:38.501 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:45:38.699 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:45:38.700 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 08:45:38.700 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-12-05 08:45:38.701 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-12-05 08:45:38.701 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-12-05 08:45:43.504 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 3 - deferring network monitor functions.
2015-12-05 08:45:43.706 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = MemoryGetId (0x20), type = Request (0x00), payload = 
2015-12-05 08:45:43.706 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:45:43.707 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:45:43.707 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:45:48.505 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:45:48.711 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:45:48.712 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:45:48.713 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:45:48.714 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:45:48.715 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:45:53.510 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:45:53.718 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:45:53.719 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:45:53.719 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:45:53.720 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:45:53.721 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:45:58.516 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:45:58.747 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:45:58.748 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 08:45:58.748 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-12-05 08:45:58.749 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-12-05 08:45:58.750 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-12-05 08:46:03.518 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 2 - deferring network monitor functions.
2015-12-05 08:46:03.763 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = 
2015-12-05 08:46:03.764 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:46:03.764 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:46:03.765 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:46:08.775 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:46:08.777 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:46:08.777 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:46:08.778 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:46:08.778 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:46:13.791 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:46:13.791 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:46:13.792 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:46:13.792 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:46:13.793 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:46:18.799 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:46:18.799 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 08:46:18.800 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-12-05 08:46:18.801 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-12-05 08:46:18.810 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-12-05 08:46:23.817 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F 
2015-12-05 08:46:23.818 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:46:23.818 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:46:23.818 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:46:28.827 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 08:46:28.828 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:46:28.828 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:46:28.829 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:46:28.829 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:46:33.833 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 08:46:33.833 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:46:33.833 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:46:33.834 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:46:33.834 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:46:38.842 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 08:46:38.843 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 08:46:38.844 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 08:46:38.845 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-12-05 08:46:38.846 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-12-05 08:46:43.851 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = GetSucNodeId (0x56), type = Request (0x00), payload =

sihui · December 5, 2015, 4:27pm

[quote=“jsable, post:22, topic:2004, full:true”]
I have had that already set up for quite a while, but I don’t know how to change it to set it to trace, and couldn’t find an example of it.[/quote]

Take a look here.
And the next look should be into the comments of that example:


jsable · December 5, 2015, 4:47pm

Thank you Sihui, I completely missed that! I changed it to trace and this is part #1:

2015-12-05 11:42:02.518 [DEBUG] [.zwave.internal.ZWaveActivator:36  ]- Z-Wave binding started. Version 1.7.1
2015-12-05 11:42:02.796 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Bath2F_Light, 018:command=Switch_Binary, refresh_interval=300)
2015-12-05 11:42:02.819 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Bath2F_Light, 018:command=Switch_Binary, refresh_interval=300)
2015-12-05 11:42:02.910 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Bath_Light, 019:command=Switch_Binary)
2015-12-05 11:42:02.927 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Bath_Light, 019:command=Switch_Binary)
2015-12-05 11:42:02.928 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Hall2F_Light, 021:command=Switch_Binary)
2015-12-05 11:42:02.928 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Hall2F_Light, 021:command=Switch_Binary)
2015-12-05 11:42:02.928 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Master_Light, 022:command=Switch_Binary)
2015-12-05 11:42:02.929 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Master_Light, 022:command=Switch_Binary)
2015-12-05 11:42:02.930 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Living_Room_Bookcase, 007:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.930 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Living_Room_Bookcase, 007:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.936 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(SunRoom_Light, 011:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.937 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(SunRoom_Light, 011:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.938 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Kitchen_Light, 012:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.950 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Kitchen_Light, 012:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.950 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Dining_Room_Light, 016:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.951 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Dining_Room_Light, 016:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.952 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Kitchen_Sink_Light, 017:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.953 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Kitchen_Sink_Light, 017:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.953 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Garage_Door_Light, 024:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.954 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Garage_Door_Light, 024:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.954 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Cabinet_Light, 025:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.955 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Cabinet_Light, 025:command=Switch_Binary,respond_to_basic=true)
2015-12-05 11:42:02.956 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Hall_Motion, 005:command=sensor_binary,sensor_type=12)
2015-12-05 11:42:02.956 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Hall_Motion, 005:command=sensor_binary,sensor_type=12)
2015-12-05 11:42:02.956 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Dining_Motion, 006:command=sensor_binary,sensor_type=12)
2015-12-05 11:42:02.957 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Dining_Motion, 006:command=sensor_binary,sensor_type=12)
2015-12-05 11:42:02.973 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(SunRoom_Door, 008:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.974 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(SunRoom_Door, 008:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.975 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Front_Door, 009:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.975 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Front_Door, 009:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.976 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Slider_Door_Sensor, 026:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.976 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Slider_Door_Sensor, 026:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.977 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(French_Door_Sensor, 028:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.977 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(French_Door_Sensor, 028:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.978 [TRACE] [.i.ZWaveGenericBindingProvider:48  ]- validateItemType(Garage_SunRoom_Sensor, 029:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.979 [TRACE] [.i.ZWaveGenericBindingProvider:57  ]- processBindingConfiguration(Garage_SunRoom_Sensor, 029:command=sensor_binary,sensor_type=10)
2015-12-05 11:42:02.998 [TRACE] [.z.internal.ZWaveActiveBinding:157 ]- allBindingsChanged
2015-12-05 11:42:03.007 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled.

jsable · December 5, 2015, 4:48pm

And part 2:

2015-12-05 11:42:03.794 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = /dev/ttyUSB0
2015-12-05 11:42:03.796 [INFO ] [.z.internal.ZWaveActiveBinding:330 ]- Update config, healtime = 2
2015-12-05 11:42:03.797 [INFO ] [.z.internal.ZWaveActiveBinding:375 ]- Update config, setSUC = true
2015-12-05 11:42:03.797 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = false
2015-12-05 11:42:03.797 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = true
2015-12-05 11:42:03.798 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding
2015-12-05 11:42:04.173 [INFO ] [b.z.i.protocol.ZWaveController:146 ]- Starting Z-Wave controller
2015-12-05 11:42:04.174 [INFO ] [b.z.i.protocol.ZWaveController:154 ]- Z-Wave timeout is set to 5000ms. Soft reset is false.
2015-12-05 11:42:04.175 [INFO ] [b.z.i.protocol.ZWaveController:407 ]- Connecting to serial port /dev/ttyUSB0
2015-12-05 11:42:04.803 [DEBUG] [WaveController$ZWaveSendThread:1244]- Starting Z-Wave thread: Send
2015-12-05 11:42:04.806 [INFO ] [b.z.i.protocol.ZWaveController:427 ]- Serial port is initialized
2015-12-05 11:42:04.809 [DEBUG] [b.z.i.protocol.ZWaveController:1201]- Starting Z-Wave thread: Input
2015-12-05 11:42:04.823 [DEBUG] [eController$ZWaveReceiveThread:1460]- Starting Z-Wave thread: Receive
2015-12-05 11:42:04.832 [TRACE] [eController$ZWaveReceiveThread:1422]- Response SENT
2015-12-05 11:42:07.813 [DEBUG] [veController$WatchDogTimerTask:176 ]- Initialising network
2015-12-05 11:42:07.863 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00)
2015-12-05 11:42:07.888 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-12-05 11:42:07.889 [TRACE] [o.b.z.i.protocol.SerialMessage:179 ]- Calculated checksum = 0xE9
2015-12-05 11:42:07.891 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 11:42:07.892 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 11:42:08.013 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 0
2015-12-05 11:42:08.015 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00)
2015-12-05 11:42:08.016 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-12-05 11:42:08.017 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00)
2015-12-05 11:42:08.018 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-12-05 11:42:08.054 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00)
2015-12-05 11:42:08.085 [TRACE] [WaveController$ZWaveSendThread:1321]- Message SENT
2015-12-05 11:42:08.099 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-12-05 11:42:08.159 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30  ]- Get SUC NodeID
2015-12-05 11:42:08.160 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00)
2015-12-05 11:42:08.168 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-12-05 11:42:08.846 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 11:42:13.089 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2015-12-05 11:42:13.091 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 11:42:13.094 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 11:42:13.095 [TRACE] [o.b.z.i.protocol.SerialMessage:179 ]- Calculated checksum = 0xE9
2015-12-05 11:42:13.096 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 11:42:13.097 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 11:42:13.102 [TRACE] [WaveController$ZWaveSendThread:1321]- Message SENT
2015-12-05 11:42:13.847 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 11:42:14.817 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-12-05 11:42:18.105 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2015-12-05 11:42:18.106 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 11:42:18.106 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 11:42:18.107 [TRACE] [o.b.z.i.protocol.SerialMessage:179 ]- Calculated checksum = 0xE9
2015-12-05 11:42:18.107 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 11:42:18.108 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 11:42:18.111 [TRACE] [WaveController$ZWaveSendThread:1321]- Message SENT
2015-12-05 11:42:18.848 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 11:42:23.113 [ERROR] [WaveController$ZWaveSendThread:1356]- NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2015-12-05 11:42:23.114 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 5
2015-12-05 11:42:23.115 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 4
2015-12-05 11:42:23.115 [TRACE] [o.b.z.i.protocol.SerialMessage:179 ]- Calculated checksum = 0xE9
2015-12-05 11:42:23.120 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-12-05 11:42:23.120 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-12-05 11:42:23.124 [TRACE] [WaveController$ZWaveSendThread:1321]- Message SENT
2015-12-05 11:42:23.849 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ]- Network Monitor: Queue length is 4 - deferring network monitor functions.
2015-12-05 11:42:24.818 [TRACE] [veController$WatchDogTimerTask:1595]- Watchdog: Checking Serial threads
2015-12-05 11:42:28.126 [WARN ] [WaveController$ZWaveSendThread:1365]- NODE 255: Too many retries. Discarding message: Message: class = GetVersion (0x15), type = Request (0x00), payload =

Now all I need is to know what to do with this information…

picarsqu3 · December 5, 2015, 5:15pm

Little bit past my current skill level at this point hoping someone more advanced than I will take notice of this and offer some advice!

jsable · December 5, 2015, 5:18pm

Thanks for the help so far, at least I got it connected and openHAB is seeing it… My only problem now is that openHAB is not seeing the devices on it. I have about 20 +/- devices that are currently on the controller, but I cannot seem to see the node ids for these devices. I used the same node ids that are on the controller (as they are assigned in Indigo 6), but the binding does not recognize them…

picarsqu3 · December 5, 2015, 5:26pm

Do you have HABmin installed? If not, I suggest installing it via this guide. Once configured, you can go into Configuration -> Bindings -> ZWave binding (are you on the latest z-wave binding btw?) and it will show you a list of your connected zwave devices.

jsable · December 5, 2015, 5:29pm

Yes, that is the guide I used when HABmin was installed. In the devices tab, there is nothing showing up at all…

picarsqu3 · December 5, 2015, 5:37pm

I wonder if you need to re-create the zwave network since you switched from Indigo. I am not sure though, since it is the same USB stick.

jsable · December 5, 2015, 5:52pm

That is what I don’t understand, I can start indigo 6 and use the zwave controls without issue. I set all of the devices in OpenHAB with the node id # that show in the config settings in indigo 6, I would think that OpenHAB would be able to connect to my z-stick and read the devices the same way, but it is not. I have tried every combination, with indigo 6 running and not running. Shut down and restarted without ever opening indigo 6 and only running OpenHAB… I think I am out of ideas at this point…

picarsqu3 · December 5, 2015, 8:03pm

I would say try excluding one device from your Indigo setup, and then add it to your OH setup. You may have to do the exclusion process on your stick as well.

jsable · December 14, 2015, 2:57am

Ok, so this can be marked as solved… Apparently the USB pasthru between Os X and VirtualBox does not work as well as advertised. I installed openHAB on a raspberry pi and 85% of my z-wave devices decided to show up.

Dr_Kuebel · May 2, 2016, 7:40pm

Unfortunately I have the same problem witz the raZberry Board.

I added the openhab user to the dialout group

I added to the openhab.cfg
`zwave:port = /dev/ttyAMA0

zwave:masterController = true
zwave:healtime = 2
zwave:softReset = false
zwave:setSUC = true`

I changed the /etc/init.d/openhab

-Dgnu.io.rxtx.SerialPorts=/dev/ttyACM0:/dev/ttyAMA0

OpenHAB 1.8.2
HABmin installed

But when I try to Include a device to the zWave I alwys get

Error sending action to the server!

tpmcleod24 · May 2, 2016, 7:49pm

For me, in OH2 on PI3, I have to set the port to /dev/ttyACM0, not AMA0. Not sure if that helps.

-tp

Dr_Kuebel · May 2, 2016, 9:10pm

no… that didn´t help…

Dr_Kuebel · May 16, 2016, 12:01pm

I tried everything, but I´m still struggeling with getting the raZberry board running…
This is the openhab.log greped for zwave
the zwave.log is completley empty

Could anybody help?

Thanks

2016-05-16 11:09:31.488 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/config/bindings/zwave on AsyncHttpConnection@30ba0f,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=5 2016-05-16 11:09:31.489 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/config/bindings/zwave @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.490 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/config/bindings/zwave @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.492 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/config/bindings/zwave -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:09:31.751 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/config/bindings/zwave 200 2016-05-16 11:09:31.835 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/nodes/ on AsyncHttpConnection@30ba0f,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=6 2016-05-16 11:09:31.837 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.839 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.846 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/nodes/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:09:31.861 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/nodes/ 406 2016-05-16 11:09:31.905 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/nodes/ on AsyncHttpConnection@30ba0f,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=7 2016-05-16 11:09:31.906 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.906 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.907 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/nodes/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:09:31.928 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/nodes/ 406 2016-05-16 11:09:31.969 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/products/ on AsyncHttpConnection@30ba0f,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=8 2016-05-16 11:09:31.970 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/products/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.971 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/products/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:31.972 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/products/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:09:31.984 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/products/ 406 2016-05-16 11:09:34.987 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/nodes/ on AsyncHttpConnection@30ba0f,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=9 2016-05-16 11:09:34.990 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:34.993 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:35.000 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/nodes/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:09:35.021 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/nodes/ 406 2016-05-16 11:09:36.220 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/action/binding/network/ on AsyncHttpConnection@30ba0f,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=10,c=4},r=10 2016-05-16 11:09:36.221 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:36.222 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:09:36.225 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/action/binding/network/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:09:36.244 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/action/binding/network/ 406 2016-05-16 11:16:26.458 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/config/bindings/zwave on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=4 2016-05-16 11:16:26.460 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/config/bindings/zwave @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.461 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/config/bindings/zwave @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.466 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/config/bindings/zwave -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:16:26.685 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/config/bindings/zwave 200 2016-05-16 11:16:26.766 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/nodes/ on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=5 2016-05-16 11:16:26.767 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.768 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.769 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/nodes/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:16:26.781 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/nodes/ 406 2016-05-16 11:16:26.822 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/nodes/ on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=6 2016-05-16 11:16:26.823 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.824 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.825 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/nodes/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:16:26.840 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/nodes/ 406 2016-05-16 11:16:26.880 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/products/ on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=7 2016-05-16 11:16:26.881 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/products/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.881 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/products/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:26.883 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/products/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:16:26.895 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/products/ 406 2016-05-16 11:16:30.267 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/action/binding/network/ on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=10,c=4},r=8 2016-05-16 11:16:30.271 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:30.274 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:16:30.279 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/action/binding/network/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:16:30.296 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/action/binding/network/ 406 2016-05-16 11:19:19.805 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/nodes/ on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=10,c=0},r=41 2016-05-16 11:19:19.809 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:19:19.812 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/nodes/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:19:19.823 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/nodes/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:19:19.839 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/nodes/ 406 2016-05-16 11:19:23.011 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/action/binding/network/ on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=10,c=7},r=43 2016-05-16 11:19:23.014 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:19:23.017 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:19:23.024 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/action/binding/network/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:19:23.048 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/action/binding/network/ 406 2016-05-16 11:19:25.434 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/action/binding/network/ on AsyncHttpConnection@15bbd6,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=10,c=4},r=45 2016-05-16 11:19:25.435 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:19:25.436 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:19:25.438 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/action/binding/network/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:19:25.449 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/action/binding/network/ 406 2016-05-16 11:55:06.974 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/action/binding/network/ on AsyncHttpConnection@a2252a,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=10,c=4},r=5 2016-05-16 11:55:06.975 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:55:06.976 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:55:06.977 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/action/binding/network/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:55:06.991 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/action/binding/network/ 406 2016-05-16 11:55:07.867 [DEBUG] [rg.eclipse.jetty.server.Server] - REQUEST /services/habmin/zwave/action/binding/network/ on AsyncHttpConnection@a2252a,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=2,l=10,c=7},r=6 2016-05-16 11:55:07.868 [DEBUG] [.server.handler.ContextHandler] - scope null||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:55:07.869 [DEBUG] [.server.handler.ContextHandler] - context=||/services/habmin/zwave/action/binding/network/ @ o.e.j.s.ServletContextHandler{/,null} 2016-05-16 11:55:07.871 [DEBUG] [e.jetty.servlet.ServletHandler] - servlet ||/services/habmin/zwave/action/binding/network/ -> org.eclipse.equinox.http.servlet.HttpServiceServlet-1 2016-05-16 11:55:07.886 [DEBUG] [rg.eclipse.jetty.server.Server] - RESPONSE /services/habmin/zwave/action/binding/network/ 406

Feanor · October 6, 2016, 2:53pm

Hi! Sorry for digging out this thread, but it just seems to fit my problem and I even implemented some of the tips found here so I hope, someone finds it and might be able to help. Thanks!

in short:

using OH 1.8.3 for Synology
using ZME_UZB1 Me USB Stick @ /dev/ttyACM0
added openhab user to dialout and uucp
adjusted owner rights of ttyACM0, lock folders, openHAB folders
running start.sh as openhab user (no init.d on synology Discstations)
openHAB starts just fine and is shown as “online” in HABmin (however sometimes it changes to ofline and back)
controler seems to be initialized correctly (see zwave log below)
Z-WAve Binding -> Devices -> Include leads to “Error sending action to the server!”

Here comes the Z-Wave DEBUG log (in two parts):

2016-10-06 16:20:15.678 [DEBUG] [.zwave.internal.ZWaveActivator:36  ]- Z-Wave binding started. Version 1.8.3
2016-10-06 16:20:15.756 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled.
2016-10-06 16:20:15.764 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = /dev/ttyACM0
2016-10-06 16:20:15.765 [INFO ] [.z.internal.ZWaveActiveBinding:330 ]- Update config, healtime = 2
2016-10-06 16:20:15.767 [INFO ] [.z.internal.ZWaveActiveBinding:375 ]- Update config, setSUC = true
2016-10-06 16:20:15.768 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = false
2016-10-06 16:20:15.769 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = true
2016-10-06 16:20:15.769 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding
2016-10-06 16:20:15.942 [INFO ] [b.z.i.protocol.ZWaveController:148 ]- Starting Z-Wave controller
2016-10-06 16:20:15.944 [INFO ] [b.z.i.protocol.ZWaveController:156 ]- Z-Wave timeout is set to 5000ms. Soft reset is false.
2016-10-06 16:20:15.946 [INFO ] [b.z.i.protocol.ZWaveController:322 ]- Connecting to serial port /dev/ttyACM0
2016-10-06 16:20:16.537 [DEBUG] [eController$ZWaveReceiveThread:1413]- Starting Z-Wave thread: Receive
2016-10-06 16:20:16.554 [INFO ] [b.z.i.protocol.ZWaveController:342 ]- Serial port is initialized
2016-10-06 16:20:16.554 [DEBUG] [b.z.i.protocol.ZWaveController:1154]- Starting Z-Wave thread: Input
2016-10-06 16:20:16.557 [DEBUG] [WaveController$ZWaveSendThread:1197]- Starting Z-Wave thread: Send
2016-10-06 16:20:19.625 [DEBUG] [veController$WatchDogTimerTask:178 ]- Initialising network
2016-10-06 16:20:19.644 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00)
2016-10-06 16:20:19.646 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 0
2016-10-06 16:20:19.648 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2016-10-06 16:20:19.650 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2016-10-06 16:20:19.652 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 0
2016-10-06 16:20:19.661 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00)
2016-10-06 16:20:19.663 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 1
2016-10-06 16:20:19.664 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 34 2E 30 35 00 01 97 
2016-10-06 16:20:19.667 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00)
2016-10-06 16:20:19.668 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 2
2016-10-06 16:20:19.672 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:19.676 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 10 01 15 5A 2D 57 61 76 65 20 34 2E 30 35 00 01 97 
2016-10-06 16:20:19.678 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00)
2016-10-06 16:20:19.679 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 3
2016-10-06 16:20:19.680 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 10 01 15 5A 2D 57 61 76 65 20 34 2E 30 35 00 01 97 
2016-10-06 16:20:19.682 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30  ]- Get SUC NodeID
2016-10-06 16:20:19.684 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 34 2E 30 35 00 01 
2016-10-06 16:20:19.684 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=0
2016-10-06 16:20:19.684 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00)
2016-10-06 16:20:19.692 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 4
2016-10-06 16:20:19.713 [DEBUG] [z.i.p.s.GetVersionMessageClass:39  ]- Got MessageGetVersion response. Version = Z-Wave 4.05, Library Type = 0x01
2016-10-06 16:20:19.715 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = GetVersion (0x15), type = Request (0x00), payload = 
2016-10-06 16:20:19.718 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 34 2E 30 35 00 01 
2016-10-06 16:20:19.719 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=GetVersion, expected=GetVersion, cancelled=false
2016-10-06 16:20:19.720 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:19.723 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:19.725 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:19.732 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 80ms/80ms.
2016-10-06 16:20:19.733 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 3
2016-10-06 16:20:19.735 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2016-10-06 16:20:19.737 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2016-10-06 16:20:19.742 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 08 01 20 D7 F3 51 94 01 36 
2016-10-06 16:20:19.748 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:19.748 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-10-06 16:20:19.750 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 08 01 20 D7 F3 51 94 01 36 
2016-10-06 16:20:19.752 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 08 01 20 D7 F3 51 94 01 36 
2016-10-06 16:20:19.754 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = MemoryGetId (0x20), type = Response (0x01), payload = D7 F3 51 94 01 
2016-10-06 16:20:19.755 [DEBUG] [.i.p.s.MemoryGetIdMessageClass:41  ]- Got MessageMemoryGetId response. Home id = 0xD7F35194, Controller Node id = 1
2016-10-06 16:20:19.757 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = MemoryGetId (0x20), type = Request (0x00), payload = 
2016-10-06 16:20:19.759 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = MemoryGetId (0x20), type = Response (0x01), payload = D7 F3 51 94 01 
2016-10-06 16:20:19.760 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=MemoryGetId, expected=MemoryGetId, cancelled=false
2016-10-06 16:20:19.761 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:19.761 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:19.762 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:19.763 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 25ms/80ms.
2016-10-06 16:20:19.764 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 2
2016-10-06 16:20:19.767 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2016-10-06 16:20:19.768 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2016-10-06 16:20:19.780 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 2B 01 07 05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 0E 
2016-10-06 16:20:19.793 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-10-06 16:20:19.793 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:19.801 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 2B 01 07 05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 0E 
2016-10-06 16:20:19.807 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 2B 01 07 05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 0E 
2016-10-06 16:20:19.814 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 
2016-10-06 16:20:19.816 [DEBUG] [ApiGetCapabilitiesMessageClass:45  ]- API Version = 5.5
2016-10-06 16:20:19.817 [DEBUG] [ApiGetCapabilitiesMessageClass:46  ]- Manufacture ID = 0x115
2016-10-06 16:20:19.818 [DEBUG] [ApiGetCapabilitiesMessageClass:47  ]- Device Type = 0x400
2016-10-06 16:20:19.819 [DEBUG] [ApiGetCapabilitiesMessageClass:48  ]- Device ID = 0x1
2016-10-06 16:20:19.820 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiGetInitData
2016-10-06 16:20:19.821 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiApplicationNodeInfo
2016-10-06 16:20:19.822 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ApplicationCommandHandler
2016-10-06 16:20:19.823 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetControllerCapabilities
2016-10-06 16:20:19.824 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiSetTimeouts
2016-10-06 16:20:19.826 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiGetCapabilities
2016-10-06 16:20:19.827 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiSoftReset
2016-10-06 16:20:19.828 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x09
2016-10-06 16:20:19.829 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x0a
2016-10-06 16:20:19.831 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RfReceiveMode
2016-10-06 16:20:19.832 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetSleepMode
2016-10-06 16:20:19.833 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendNodeInfo
2016-10-06 16:20:19.834 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendData
2016-10-06 16:20:19.835 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendDataMulti
2016-10-06 16:20:19.838 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetVersion
2016-10-06 16:20:19.839 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendDataAbort
2016-10-06 16:20:19.840 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RfPowerLevelSet
2016-10-06 16:20:19.841 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendDataMeta
2016-10-06 16:20:19.841 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetRandom
2016-10-06 16:20:19.842 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: MemoryGetId
2016-10-06 16:20:19.843 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: MemoryGetByte
2016-10-06 16:20:19.844 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: MemoryPutByte
2016-10-06 16:20:19.845 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReadMemory
2016-10-06 16:20:19.846 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: WriteMemory
2016-10-06 16:20:19.847 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x27
2016-10-06 16:20:19.848 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x28
2016-10-06 16:20:19.849 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x29
2016-10-06 16:20:19.850 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2a
2016-10-06 16:20:19.851 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2b
2016-10-06 16:20:19.852 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2c
2016-10-06 16:20:19.853 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2d
2016-10-06 16:20:19.855 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: IdentifyNode
2016-10-06 16:20:19.856 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetDefault
2016-10-06 16:20:19.857 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReplicationCommandComplete
2016-10-06 16:20:19.858 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReplicationSendData
2016-10-06 16:20:19.859 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: AssignReturnRoute
2016-10-06 16:20:19.860 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: DeleteReturnRoute
2016-10-06 16:20:19.861 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RequestNodeNeighborUpdate
2016-10-06 16:20:19.861 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ApplicationUpdate
2016-10-06 16:20:19.862 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: AddNodeToNetwork
2016-10-06 16:20:19.863 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RemoveNodeFromNetwork
2016-10-06 16:20:19.864 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: CreateNewPrimary
2016-10-06 16:20:19.864 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ControllerChange
2016-10-06 16:20:19.865 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetLearnMode
2016-10-06 16:20:19.866 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: AssignSucReturnRoute
2016-10-06 16:20:19.867 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RequestNetworkUpdate
2016-10-06 16:20:19.868 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetSucNodeID
2016-10-06 16:20:19.869 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: DeleteSUCReturnRoute
2016-10-06 16:20:19.870 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetSucNodeId
2016-10-06 16:20:19.871 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendSucId
2016-10-06 16:20:19.872 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x5e
2016-10-06 16:20:19.873 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RequestNodeInfo
2016-10-06 16:20:19.874 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RemoveFailedNodeID
2016-10-06 16:20:19.875 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: IsFailedNodeID
2016-10-06 16:20:19.876 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReplaceFailedNode
2016-10-06 16:20:19.877 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x66
2016-10-06 16:20:19.878 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x67
2016-10-06 16:20:19.879 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x78
2016-10-06 16:20:19.879 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetRoutingInfo
2016-10-06 16:20:19.880 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: LockRoute
2016-10-06 16:20:19.881 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x92
2016-10-06 16:20:19.882 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x93
2016-10-06 16:20:19.883 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x98
2016-10-06 16:20:19.884 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xb4
2016-10-06 16:20:19.885 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: WatchDogKick
2016-10-06 16:20:19.886 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: WatchDogDisable
2016-10-06 16:20:19.887 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xb8
2016-10-06 16:20:19.888 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xb9
2016-10-06 16:20:19.889 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RfPowerLevelSet
2016-10-06 16:20:19.890 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetLibraryType
2016-10-06 16:20:19.891 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendTestFrame
2016-10-06 16:20:19.892 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetProtocolStatus
2016-10-06 16:20:19.893 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xd2
2016-10-06 16:20:19.894 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xd3
2016-10-06 16:20:19.896 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xd4
2016-10-06 16:20:19.897 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xef
2016-10-06 16:20:19.898 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xf2
2016-10-06 16:20:19.899 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xf4
2016-10-06 16:20:19.900 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xf5

continued in next post

Feanor · October 6, 2016, 2:53pm

2016-10-06 16:20:19.901 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = 
2016-10-06 16:20:19.908 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 
2016-10-06 16:20:19.910 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SerialApiGetCapabilities, expected=SerialApiGetCapabilities, cancelled=false
2016-10-06 16:20:19.911 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:19.912 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:19.913 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:19.915 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 145ms/145ms.
2016-10-06 16:20:19.920 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetInitData (0x02), type = Request (0x00)
2016-10-06 16:20:19.921 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 3
2016-10-06 16:20:19.923 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 2
2016-10-06 16:20:19.925 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2016-10-06 16:20:19.928 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2016-10-06 16:20:19.932 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 05 01 06 96 0F 64 
2016-10-06 16:20:19.935 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-10-06 16:20:19.936 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:19.938 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 01 06 96 0F 64 
2016-10-06 16:20:19.940 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 05 01 06 96 0F 64 
2016-10-06 16:20:19.942 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F 
2016-10-06 16:20:19.944 [DEBUG] [rialApiSetTimeoutsMessageClass:40  ]- Got SerialApiSetTimeouts response. ACK=150, BYTE=15
2016-10-06 16:20:19.946 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F 
2016-10-06 16:20:19.948 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F 
2016-10-06 16:20:19.949 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SerialApiSetTimeouts, expected=SerialApiSetTimeouts, cancelled=false
2016-10-06 16:20:19.950 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:19.951 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:19.952 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:19.954 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 24ms/145ms.
2016-10-06 16:20:19.955 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 1
2016-10-06 16:20:19.957 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2016-10-06 16:20:19.958 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2016-10-06 16:20:19.962 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 04 01 56 01 AD 
2016-10-06 16:20:19.966 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-10-06 16:20:19.967 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:19.968 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 56 01 AD 
2016-10-06 16:20:19.970 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 04 01 56 01 AD 
2016-10-06 16:20:19.971 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 01 
2016-10-06 16:20:19.972 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:41  ]- Got SUC NodeID response.
2016-10-06 16:20:19.973 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:44  ]- NODE 1: Node is SUC.
2016-10-06 16:20:19.974 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = 
2016-10-06 16:20:19.976 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 01 
2016-10-06 16:20:19.977 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=GetSucNodeId, expected=GetSucNodeId, cancelled=false
2016-10-06 16:20:19.978 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:19.979 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:19.980 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:19.982 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 23ms/145ms.
2016-10-06 16:20:19.985 [DEBUG] [rollerCapabilitiesMessageClass:41  ]- Creating GET_CONTROLLER_CAPABILITIES message
2016-10-06 16:20:19.987 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetControllerCapabilities (0x05), type = Request (0x00)
2016-10-06 16:20:19.988 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 2
2016-10-06 16:20:19.990 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 1
2016-10-06 16:20:19.992 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 02 FE 
2016-10-06 16:20:19.994 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 03 00 02 FE 
2016-10-06 16:20:20.092 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 25 01 02 05 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 CD 
2016-10-06 16:20:20.101 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-10-06 16:20:20.101 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:20.105 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 25 01 02 05 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 CD 
2016-10-06 16:20:20.109 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 25 01 02 05 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 CD 
2016-10-06 16:20:20.114 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 
2016-10-06 16:20:20.116 [DEBUG] [rialApiGetInitDataMessageClass:39  ]- Got MessageSerialApiGetInitData response.
2016-10-06 16:20:20.119 [INFO ] [rialApiGetInitDataMessageClass:57  ]- NODE 1: Node found
2016-10-06 16:20:20.121 [INFO ] [rialApiGetInitDataMessageClass:65  ]- ZWave Controller using Controller API
2016-10-06 16:20:20.122 [INFO ] [rialApiGetInitDataMessageClass:66  ]- ZWave Controller is Primary Controller
2016-10-06 16:20:20.124 [INFO ] [rialApiGetInitDataMessageClass:67  ]- ------------Number of Nodes Found Registered to ZWave Controller------------
2016-10-06 16:20:20.131 [INFO ] [rialApiGetInitDataMessageClass:68  ]- # Nodes = 1
2016-10-06 16:20:20.132 [INFO ] [rialApiGetInitDataMessageClass:69  ]- ----------------------------------------------------------------------------
2016-10-06 16:20:20.133 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SerialApiGetInitData (0x02), type = Request (0x00), payload = 
2016-10-06 16:20:20.137 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 
2016-10-06 16:20:20.139 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SerialApiGetInitData, expected=SerialApiGetInitData, cancelled=false
2016-10-06 16:20:20.139 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:20.140 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:20.142 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:20.144 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 150ms/150ms.
2016-10-06 16:20:20.150 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 0
2016-10-06 16:20:20.151 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 05 F9 
2016-10-06 16:20:20.153 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 03 00 05 F9 
2016-10-06 16:20:20.155 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- NODE 1: Init node thread start
2016-10-06 16:20:20.157 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 04 01 05 3C C3 
2016-10-06 16:20:20.160 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-10-06 16:20:20.160 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:20.162 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 05 3C C3 
2016-10-06 16:20:20.164 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 04 01 05 3C C3 
2016-10-06 16:20:20.165 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 3C 
2016-10-06 16:20:20.167 [DEBUG] [rollerCapabilitiesMessageClass:55  ]- Controller is secondary = false
2016-10-06 16:20:20.169 [DEBUG] [rollerCapabilitiesMessageClass:56  ]- Controller is on other network = false
2016-10-06 16:20:20.170 [DEBUG] [rollerCapabilitiesMessageClass:57  ]- Node ID Server is present = false
2016-10-06 16:20:20.172 [DEBUG] [rollerCapabilitiesMessageClass:58  ]- Controller is real primary = true
2016-10-06 16:20:20.173 [DEBUG] [rollerCapabilitiesMessageClass:59  ]- Controller is SUC = true
2016-10-06 16:20:20.185 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload = 
2016-10-06 16:20:20.186 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 3C 
2016-10-06 16:20:20.187 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=GetControllerCapabilities, expected=GetControllerCapabilities, cancelled=false
2016-10-06 16:20:20.188 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:20.189 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:20.191 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:20.196 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 42ms/150ms.
2016-10-06 16:20:21.156 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 1: Serializing from file etc/zwave/node1.xml
2016-10-06 16:20:21.306 [DEBUG] [b.z.i.protocol.ZWaveController:529 ]- NODE 1: Restore from config: Ok.
2016-10-06 16:20:21.377 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:269 ]- NODE 1: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-10-06 16:20:21.379 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1131]- NODE 1: Initialisation retry timer started 5000
2016-10-06 16:20:21.381 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:335 ]- NODE 1: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-10-06 16:20:21.382 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:340 ]- NODE 1: Node advancer: Initialisation starting
2016-10-06 16:20:21.384 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:868 ]- NODE 1: Node advancer - advancing to PROTOINFO
2016-10-06 16:20:21.385 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:335 ]- NODE 1: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-10-06 16:20:21.386 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:349 ]- NODE 1: Node advancer: PROTOINFO - send IdentifyNode
2016-10-06 16:20:21.389 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2016-10-06 16:20:21.391 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 0
2016-10-06 16:20:21.392 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 00 41 01 BB 
2016-10-06 16:20:21.394 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 0
2016-10-06 16:20:21.394 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 
2016-10-06 16:20:21.395 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:242 ]- NODE 1: Node advancer - queued packet. Queue length is 1
2016-10-06 16:20:21.397 [DEBUG] [b.z.i.protocol.ZWaveController:585 ]- NODE 1: Init node thread finished
2016-10-06 16:20:21.400 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 09 01 41 93 16 01 02 02 01 33 
2016-10-06 16:20:21.406 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:21.407 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 01 41 93 16 01 02 02 01 33 
2016-10-06 16:20:21.409 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 09 01 41 93 16 01 02 02 01 33 
2016-10-06 16:20:21.410 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 93 16 01 02 02 01 
2016-10-06 16:20:21.411 [DEBUG] [i.p.s.IdentifyNodeMessageClass:52  ]- NODE 1: ProtocolInfo
2016-10-06 16:20:21.412 [DEBUG] [i.p.s.IdentifyNodeMessageClass:68  ]- NODE 1: Listening = true
2016-10-06 16:20:21.413 [DEBUG] [i.p.s.IdentifyNodeMessageClass:69  ]- NODE 1: Routing = false
2016-10-06 16:20:21.414 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=0
2016-10-06 16:20:21.415 [DEBUG] [i.p.s.IdentifyNodeMessageClass:70  ]- NODE 1: Beaming = true
2016-10-06 16:20:21.416 [DEBUG] [i.p.s.IdentifyNodeMessageClass:71  ]- NODE 1: Version = 4
2016-10-06 16:20:21.417 [DEBUG] [i.p.s.IdentifyNodeMessageClass:72  ]- NODE 1: FLIRS = false
2016-10-06 16:20:21.418 [DEBUG] [i.p.s.IdentifyNodeMessageClass:73  ]- NODE 1: Security = false
2016-10-06 16:20:21.418 [DEBUG] [i.p.s.IdentifyNodeMessageClass:74  ]- NODE 1: Max Baud = 40000
2016-10-06 16:20:21.419 [DEBUG] [i.p.s.IdentifyNodeMessageClass:89  ]- NODE 1: Basic = Static Controller
2016-10-06 16:20:21.421 [DEBUG] [i.p.s.IdentifyNodeMessageClass:96  ]- NODE 1: Generic = Static Controller
2016-10-06 16:20:21.422 [DEBUG] [i.p.s.IdentifyNodeMessageClass:103 ]- NODE 1: Specific = PC Controller
2016-10-06 16:20:21.424 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:225 ]- NODE 1: Creating new instance of command class NO_OPERATION
2016-10-06 16:20:21.426 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:225 ]- NODE 1: Creating new instance of command class BASIC
2016-10-06 16:20:21.428 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 01 
2016-10-06 16:20:21.429 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 93 16 01 02 02 01 
2016-10-06 16:20:21.434 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=IdentifyNode, expected=IdentifyNode, cancelled=false
2016-10-06 16:20:21.435 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:21.436 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:21.437 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:21.439 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1013]- NODE 1: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2016-10-06 16:20:21.440 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:203 ]- NODE 1: Node advancer - checking initialisation queue. Queue size 1.
2016-10-06 16:20:21.441 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:209 ]- NODE 1: Node advancer - message removed from queue. Queue size 0.
2016-10-06 16:20:21.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:269 ]- NODE 1: Node advancer - PROTOINFO: queue length(0), free to send(true)
2016-10-06 16:20:21.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1131]- NODE 1: Initialisation retry timer started 5000
2016-10-06 16:20:21.451 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:335 ]- NODE 1: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2016-10-06 16:20:21.452 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:868 ]- NODE 1: Node advancer - advancing to NEIGHBORS
2016-10-06 16:20:21.453 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:335 ]- NODE 1: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2016-10-06 16:20:21.454 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:359 ]- NODE 1: Node advancer: NEIGHBORS - send RoutingInfo
2016-10-06 16:20:21.456 [DEBUG] [p.s.GetRoutingInfoMessageClass:29  ]- NODE 1: Request routing info
2016-10-06 16:20:21.457 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00)
2016-10-06 16:20:21.458 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 1
2016-10-06 16:20:21.459 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:242 ]- NODE 1: Node advancer - queued packet. Queue length is 1
2016-10-06 16:20:21.460 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 64ms/150ms.
2016-10-06 16:20:21.462 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 0
2016-10-06 16:20:21.463 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 80 01 00 00 03 7A 
2016-10-06 16:20:21.465 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 255: Sending REQUEST Message = 01 07 00 80 01 00 00 03 7A 
2016-10-06 16:20:21.473 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 20 01 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5E 
2016-10-06 16:20:21.479 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-10-06 16:20:21.482 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 20 01 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5E 
2016-10-06 16:20:21.484 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=0
2016-10-06 16:20:21.497 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 20 01 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5E 
2016-10-06 16:20:21.500 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2016-10-06 16:20:21.501 [DEBUG] [p.s.GetRoutingInfoMessageClass:47  ]- NODE 1: Got NodeRoutingInfo request.
2016-10-06 16:20:21.503 [DEBUG] [p.s.GetRoutingInfoMessageClass:71  ]- NODE 1: No neighbors reported
2016-10-06 16:20:21.509 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveNetworkEvent
2016-10-06 16:20:21.510 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:21.515 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 01 00 00 03 
2016-10-06 16:20:21.517 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2016-10-06 16:20:21.518 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=GetRoutingInfo, expected=GetRoutingInfo, cancelled=false
2016-10-06 16:20:21.518 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-10-06 16:20:21.519 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-06 16:20:21.520 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-10-06 16:20:21.521 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1013]- NODE 1: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-10-06 16:20:21.578 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:203 ]- NODE 1: Node advancer - checking initialisation queue. Queue size 1.
2016-10-06 16:20:21.579 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:209 ]- NODE 1: Node advancer - message removed from queue. Queue size 0.
2016-10-06 16:20:21.580 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:269 ]- NODE 1: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2016-10-06 16:20:21.582 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1131]- NODE 1: Initialisation retry timer started 5000
2016-10-06 16:20:21.583 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:335 ]- NODE 1: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2016-10-06 16:20:21.585 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:868 ]- NODE 1: Node advancer - advancing to FAILED_CHECK
2016-10-06 16:20:21.586 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:335 ]- NODE 1: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-10-06 16:20:21.587 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:368 ]- NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation
2016-10-06 16:20:21.589 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:335 ]- NODE 1: Node advancer: loop - DONE try 0: stageAdvanced(true)
2016-10-06 16:20:21.590 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:107 ]- NODE 1: Serializing to file etc/zwave/node1.xml
2016-10-06 16:20:21.694 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:827 ]- NODE 1: Node advancer: Initialisation complete!
2016-10-06 16:20:21.695 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveInitializationCompletedEvent
2016-10-06 16:20:21.697 [DEBUG] [.z.internal.ZWaveActiveBinding:425 ]- NODE 1: ZWaveIncomingEvent Called, Network Event, Init Done. Setting device ready.
2016-10-06 16:20:21.698 [DEBUG] [z.internal.ZWaveNetworkMonitor:730 ]- Network initialised - starting network monitor.
2016-10-06 16:20:21.700 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 255: Response processed after 234ms/234ms.
2016-10-06 16:21:55.991 [DEBUG] [z.internal.ZWaveNetworkMonitor:353 ]- Network Monitor: No nodes to ping!
2016-10-06 16:23:26.170 [DEBUG] [z.internal.ZWaveNetworkMonitor:353 ]- Network Monitor: No nodes to ping!
2016-10-06 16:24:56.339 [DEBUG] [z.internal.ZWaveNetworkMonitor:353 ]- Network Monitor: No nodes to ping!

last message is repeated every 1.5 minutes.
Thanks for your help!