ZWave binding updates

Yeah i made a mistake there. I’ll disconnect Socat (which i’m currently using and will post the result here)

The error i got after filling in the network details is:

Z-Wave Serial Controller

Status: OFFLINE - COMMUNICATION_ERROR Serial Error: Unsupported operation on port rfc2217://192.168.1.206:4004

A bit of log file.

01-Sep-2019 16:26:42.423 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update port to rfc2217://192.168.1.206:4004
01-Sep-2019 16:26:42.424 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_master to true
01-Sep-2019 16:26:42.424 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update inclusion_mode to 2
01-Sep-2019 16:26:42.425 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_wakeupperiod to 3600
01-Sep-2019 16:26:42.426 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update heal_time to 2
01-Sep-2019 16:26:42.428 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 10 hours time.
01-Sep-2019 16:26:42.429 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_exclude to false
01-Sep-2019 16:26:42.430 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_inclusiontimeout to 30
01-Sep-2019 16:26:42.435 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_hardreset to false
01-Sep-2019 16:26:42.466 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
01-Sep-2019 16:26:44.416 [TRACE] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions
01-Sep-2019 16:26:44.418 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 255: TID 302: Timeout at state WAIT_RESPONSE. 3 retries remaining.
01-Sep-2019 16:26:44.419 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 302: Transaction is current transaction, so clearing!!!!!
01-Sep-2019 16:26:44.420 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 302: Transaction CANCELLED
01-Sep-2019 16:26:44.422 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
01-Sep-2019 16:26:44.422 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:302 CANCELLED
01-Sep-2019 16:26:44.431 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
01-Sep-2019 16:26:44.432 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 7: listening == false, frequentlyListening == false, awake == false
01-Sep-2019 16:26:44.434 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
01-Sep-2019 16:26:44.436 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
01-Sep-2019 16:26:44.437 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
01-Sep-2019 16:26:45.468 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
01-Sep-2019 16:26:45.469 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
01-Sep-2019 16:26:45.470 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:f54930dc.
01-Sep-2019 16:26:45.471 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 10 hours time.
01-Sep-2019 16:26:45.470 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Interrupted taking message from recvQueue
java.lang.InterruptedException: null
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014) ~[?:?]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048) ~[?:?]
        at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:433) [302:org.openhab.binding.zwave:2.5.0.201908282134]
01-Sep-2019 16:26:45.472 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
01-Sep-2019 16:26:45.473 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
01-Sep-2019 16:26:45.473 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port 'rfc2217://192.168.1.206:4004'
01-Sep-2019 16:26:45.473 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 7: listening == false, frequentlyListening == false, awake == false
01-Sep-2019 16:26:45.477 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
01-Sep-2019 16:26:45.477 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
01-Sep-2019 16:29:28.779 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 10: ZWaveCommandClassTransactionPayload - send to node
01-Sep-2019 16:29:28.781 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 10: Encapsulating message, endpoint 0
01-Sep-2019 16:29:28.782 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
01-Sep-2019 16:29:28.782 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured
01-Sep-2019 16:29:28.783 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@152749b
01-Sep-2019 16:29:28.785 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
01-Sep-2019 16:29:28.786 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Added 303 to queue - size 2
01-Sep-2019 16:29:28.788 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
01-Sep-2019 16:29:28.789 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 7: listening == false, frequentlyListening == false, awake == false
01-Sep-2019 16:29:28.790 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
01-Sep-2019 16:29:28.791 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 10: listening == true, frequentlyListening == false, awake == false
01-Sep-2019 16:29:28.792 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
01-Sep-2019 16:29:28.793 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
01-Sep-2019 16:29:28.793 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 10: Creating empty message of class = SendData (0x13), type = Request
01-Sep-2019 16:29:28.794 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 46
01-Sep-2019 16:29:28.796 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 0A 01 00 25 E4 2E 
01-Sep-2019 16:29:28.799 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 08 00 13 0A 01 00 25 E4 2E 
01-Sep-2019 16:29:28.813 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
01-Sep-2019 16:29:28.814 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 303: Transaction Start type SendData 
01-Sep-2019 16:29:28.814 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 303: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 228
01-Sep-2019 16:29:28.815 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
01-Sep-2019 16:29:28.816 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
01-Sep-2019 16:29:28.817 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
01-Sep-2019 16:29:28.820 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Sep 01 16:29:30 BST 2019 - 2000ms
01-Sep-2019 16:29:28.821 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 303: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 228
01-Sep-2019 16:29:28.822 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
01-Sep-2019 16:29:28.823 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Sep 01 16:29:30 BST 2019 - 1994ms
01-Sep-2019 16:29:30.817 [TRACE] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions
01-Sep-2019 16:29:30.819 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 10: TID 303: Timeout at state WAIT_RESPONSE. 3 retries remaining.
01-Sep-2019 16:29:30.820 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
01-Sep-2019 16:29:30.821 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 303: Transaction ABORTED

I’ve restarted Openhab, now only using the remote connection. This is the log file:

01-Sep-2019 17:40:44.686 [DEBUG] [org.openhab.binding.zwave                         ] - BundleEvent STARTING - org.openhab.binding.zwave
01-Sep-2019 17:40:44.901 [DEBUG] [org.openhab.binding.zwave                         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigOptionProvider}={service.id=523, service.bundleid=302, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveConfigProvider, component.id=346} - org.openhab.binding.zwave
01-Sep-2019 17:40:44.922 [DEBUG] [org.openhab.binding.zwave                         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=524, service.bundleid=302, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=347} - org.openhab.binding.zwave
01-Sep-2019 17:40:44.933 [DEBUG] [org.openhab.binding.zwave                         ] - BundleEvent STARTED - org.openhab.binding.zwave
01-Sep-2019 17:40:52.199 [DEBUG] [nhab.binding.zwave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:f54930dc with scan time of 60
01-Sep-2019 17:40:52.203 [DEBUG] [nhab.binding.zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:f54930dc
01-Sep-2019 17:40:52.204 [INFO ] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
01-Sep-2019 17:40:52.211 [DEBUG] [org.openhab.binding.zwave                         ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=534, service.bundleid=302, service.scope=singleton} - org.openhab.binding.zwave
01-Sep-2019 17:40:52.430 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
01-Sep-2019 17:40:52.432 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:f54930dc.
01-Sep-2019 17:40:52.435 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 9 hours time.
01-Sep-2019 17:40:52.442 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port 'rfc2217://192.168.1.206:4004'

Hey
What Software did you use?
Cheers

Hello, I use this one ZWavePCController_v5_38 and Zensys tool

1 Like

not sure if this is same isue but i get very sluggish response from z devices after upgrading to M3

18-Sep-2019 20:07:09.453 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
18-Sep-2019 20:08:28.885 [INFO ] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
18-Sep-2019 20:08:28.961 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
18-Sep-2019 20:09:27.272 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
18-Sep-2019 20:09:27.274 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM1'
18-Sep-2019 20:09:35.942 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
18-Sep-2019 20:09:35.946 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
18-Sep-2019 20:13:50.256 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
18-Sep-2019 20:16:06.825 [INFO ] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
18-Sep-2019 20:16:06.922 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
18-Sep-2019 20:28:10.067 [INFO ] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
18-Sep-2019 20:28:10.122 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
18-Sep-2019 20:28:10.201 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
18-Sep-2019 20:28:10.241 [INFO ] [ab.binding.zwave.internal.protocol.ZWaveController] - Starting ZWave controller
18-Sep-2019 20:28:10.241 [INFO ] [ab.binding.zwave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
18-Sep-2019 20:28:10.620 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.

Same issue as what exactly? There’s not really a current conversation going on here so I’m not sure what you’re referring to. Please can you explain your problem?

Please provide a debug log and I’ll take a quick look.

Sorry Chris, was referring to

seemed to be lots of those in threads above

Just looking up how to do a debug and what to do with it

@chris is this enough for the log?

18-Sep-2019 22:32:52.275 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
18-Sep-2019 22:32:52.275 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18-Sep-2019 22:32:52.276 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.276 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.276 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.276 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
18-Sep-2019 22:32:52.276 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.277 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1404: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 195
18-Sep-2019 22:32:52.277 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.277 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
18-Sep-2019 22:32:52.278 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Transaction already in queue - removed original
18-Sep-2019 22:32:52.278 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Added 1549 to queue - size 37
18-Sep-2019 22:32:52.278 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 11: Adding to device queue
18-Sep-2019 22:32:52.278 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 11: Added 1548 to queue - size 38
18-Sep-2019 22:32:52.279 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.279 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.282 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 00 E9 
18-Sep-2019 22:32:52.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00 
18-Sep-2019 22:32:52.283 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
18-Sep-2019 22:32:52.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.283 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
18-Sep-2019 22:32:52.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.284 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
18-Sep-2019 22:32:52.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 3<>125 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.284 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
18-Sep-2019 22:32:52.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 4<>124 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.284 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
18-Sep-2019 22:32:52.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 5<>123 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.284 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
18-Sep-2019 22:32:52.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 6<>122 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.285 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (6): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00 
18-Sep-2019 22:32:52.285 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 1404: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 195
18-Sep-2019 22:32:52.289 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 07 0E 32 02 21 74 00 00 29 39 00 00 00 00 00 00 93 
18-Sep-2019 22:32:52.289 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 27: Adding to device queue
18-Sep-2019 22:32:52.289 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 27: Added 1547 to queue - size 39
18-Sep-2019 22:32:52.289 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.289 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 6<>122 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=7, callback=0, payload=00 07 0E 32 02 21 74 00 00 29 39 00 00 00 00 00 00 
18-Sep-2019 22:32:52.289 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue
18-Sep-2019 22:32:52.290 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: Added 1546 to queue - size 40
18-Sep-2019 22:32:52.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.290 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.290 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 C0 01 00 01 2B 
18-Sep-2019 22:32:52.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
18-Sep-2019 22:32:52.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Added 1545 to queue - size 41
18-Sep-2019 22:32:52.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 7<>121 : Message: class=SendData[19], type=Request[0], dest=1, callback=192, payload=C0 01 00 01 
18-Sep-2019 22:32:52.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.290 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling initialised at 1800 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
18-Sep-2019 22:32:52.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added 1544 to queue - size 42
18-Sep-2019 22:32:52.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.291 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 28: Adding to device queue
18-Sep-2019 22:32:52.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 28: Added 1543 to queue - size 43
18-Sep-2019 22:32:52.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.292 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 28: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.296 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: Adding to device queue
18-Sep-2019 22:32:52.296 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: Added 1542 to queue - size 44
18-Sep-2019 22:32:52.296 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.296 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.297 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 14: Adding to device queue
18-Sep-2019 22:32:52.297 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 14: Added 1541 to queue - size 45
18-Sep-2019 22:32:52.297 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.297 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 14: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.301 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18-Sep-2019 22:32:52.302 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 1404: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 195
18-Sep-2019 22:32:52.302 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00 
18-Sep-2019 22:32:52.302 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.302 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Transaction already in queue - removed original
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Added 1550 to queue - size 45
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Transaction already in queue - removed original
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Added 1551 to queue - size 45
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Transaction already in queue - removed original
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Added 1552 to queue - size 45
18-Sep-2019 22:32:52.303 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Transaction already in queue - removed original
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Added 1553 to queue - size 45
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Transaction already in queue - removed original
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Added 1554 to queue - size 45
18-Sep-2019 22:32:52.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.320 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 10: sentData was not placed on stack.
18-Sep-2019 22:32:52.322 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 1B 0E 32 02 21 64 00 00 0C 2C 02 58 00 00 0C 2C D5 
18-Sep-2019 22:32:52.322 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 8<>120 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=27, callback=0, payload=00 1B 0E 32 02 21 64 00 00 0C 2C 02 58 00 00 0C 2C 
18-Sep-2019 22:32:52.323 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 1404: Transaction CANCELLED
18-Sep-2019 22:32:52.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
18-Sep-2019 22:32:52.323 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:zwavecontroller:node11:switch_binary --> OFF [OnOffType]
18-Sep-2019 22:32:52.323 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
18-Sep-2019 22:32:52.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: CANCEL while sending message. Requeueing - 2 attempts left!
18-Sep-2019 22:32:52.323 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 1404: Transaction RESET with 2 retries remaining.
18-Sep-2019 22:32:52.323 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 11: Creating new message for application command SWITCH_BINARY_SET
18-Sep-2019 22:32:52.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
18-Sep-2019 22:32:52.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Added 1404 to queue - size 46
18-Sep-2019 22:32:52.323 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 11: SECURITY not supported
18-Sep-2019 22:32:52.323 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: TID 1404: Transaction not completed
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (8): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.324 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 11: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 11: Adding to device queue
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (7): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (6): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (5): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (4): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 11: Transaction already in queue - removed original
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (3): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=7, callback=0, payload=00 07 0E 32 02 21 74 00 00 29 39 00 00 00 00 00 00 
18-Sep-2019 22:32:52.325 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.325 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 7: Application Command Request (ALIVE:DONE)
18-Sep-2019 22:32:52.325 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 7: resetResendCount initComplete=true isDead=false
18-Sep-2019 22:32:52.325 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 7: Incoming command class COMMAND_CLASS_METER, endpoint 0
18-Sep-2019 22:32:52.325 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 7: SECURITY NOT required on COMMAND_CLASS_METER
18-Sep-2019 22:32:52.325 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 7: Received COMMAND_CLASS_METER V3 METER_REPORT
18-Sep-2019 22:32:52.325 [DEBUG] [ernal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 7: Meter: Type=Electric(1), Scale=W(2), Value=10.553
18-Sep-2019 22:32:52.325 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveMeterValueEvent
18-Sep-2019 22:32:52.325 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 7: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=10.553
18-Sep-2019 22:32:52.326 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating channel state zwave:device:zwavecontroller:node7:meter_watts to 10.553 [DecimalType]
18-Sep-2019 22:32:52.326 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 7: Commands processed 1.
18-Sep-2019 22:32:52.326 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 7: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1af2813.
18-Sep-2019 22:32:52.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 11: Added 1555 to queue - size 46
18-Sep-2019 22:32:52.327 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.327 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.329 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18-Sep-2019 22:32:52.329 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18-Sep-2019 22:32:52.330 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=SendData[19], type=Request[0], dest=1, callback=192, payload=C0 01 00 01 
18-Sep-2019 22:32:52.330 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.331 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
18-Sep-2019 22:32:52.331 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: null
18-Sep-2019 22:32:52.332 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Command received zwave:device:zwavecontroller:node16:switch_binary2 --> OFF [OnOffType]
18-Sep-2019 22:32:52.332 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=192, payload=C0 01 00 01 
18-Sep-2019 22:32:52.332 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 17: Command received zwave:device:zwavecontroller:node17:switch_binary --> OFF [OnOffType]
18-Sep-2019 22:32:52.332 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=27, callback=0, payload=00 1B 0E 32 02 21 64 00 00 0C 2C 02 58 00 00 0C 2C 
18-Sep-2019 22:32:52.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 27: Application Command Request (ALIVE:DONE)
18-Sep-2019 22:32:52.345 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 17: Creating new message for application command SWITCH_BINARY_SET
18-Sep-2019 22:32:52.345 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 16: Creating new message for application command SWITCH_BINARY_SET
18-Sep-2019 22:32:52.346 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 17: SECURITY not supported
18-Sep-2019 22:32:52.346 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Encapsulating message, instance / endpoint 2
18-Sep-2019 22:32:52.346 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 17: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
18-Sep-2019 22:32:52.346 [DEBUG] [otocol.commandclass.ZWaveMultiInstanceCommandClass] - NODE 16: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: Adding to device queue
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: Transaction already in queue - removed original
18-Sep-2019 22:32:52.346 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: Added 1556 to queue - size 46
18-Sep-2019 22:32:52.346 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
18-Sep-2019 22:32:52.346 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Transaction already in queue - removed original
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added 1557 to queue - size 46
18-Sep-2019 22:32:52.346 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.346 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.352 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 27: resetResendCount initComplete=true isDead=false
18-Sep-2019 22:32:52.352 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 27: Incoming command class COMMAND_CLASS_METER, endpoint 0
18-Sep-2019 22:32:52.352 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 27: SECURITY NOT required on COMMAND_CLASS_METER
18-Sep-2019 22:32:52.352 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 27: Received COMMAND_CLASS_METER V3 METER_REPORT
18-Sep-2019 22:32:52.353 [DEBUG] [ernal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 27: Meter: Type=Electric(1), Scale=kWh(0), Value=3.116
18-Sep-2019 22:32:52.353 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 27: Got an event from Z-Wave network: ZWaveMeterValueEvent
18-Sep-2019 22:32:52.353 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 27: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=3.116
18-Sep-2019 22:32:52.353 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 27: Updating channel state zwave:device:zwavecontroller:node27:meter_kwh to 3.116 [DecimalType]
18-Sep-2019 22:32:52.354 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 27: Commands processed 1.
18-Sep-2019 22:32:52.354 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 27: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a86b06.
18-Sep-2019 22:32:52.354 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18-Sep-2019 22:32:52.354 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18-Sep-2019 22:32:52.355 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.355 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.366 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Command received zwave:device:zwavecontroller:node16:switch_binary2 --> OFF [OnOffType]
18-Sep-2019 22:32:52.366 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 16: Creating new message for application command SWITCH_BINARY_SET
18-Sep-2019 22:32:52.366 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Encapsulating message, instance / endpoint 2
18-Sep-2019 22:32:52.366 [DEBUG] [otocol.commandclass.ZWaveMultiInstanceCommandClass] - NODE 16: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
18-Sep-2019 22:32:52.366 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
18-Sep-2019 22:32:52.366 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
18-Sep-2019 22:32:52.366 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
18-Sep-2019 22:32:52.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Transaction already in queue - removed original
18-Sep-2019 22:32:52.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added 1558 to queue - size 46
18-Sep-2019 22:32:52.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.367 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.372 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Command received zwave:device:zwavecontroller:node16:switch_binary2 --> OFF [OnOffType]
18-Sep-2019 22:32:52.372 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 16: Creating new message for application command SWITCH_BINARY_SET
18-Sep-2019 22:32:52.372 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Encapsulating message, instance / endpoint 2
18-Sep-2019 22:32:52.372 [DEBUG] [otocol.commandclass.ZWaveMultiInstanceCommandClass] - NODE 16: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
18-Sep-2019 22:32:52.372 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
18-Sep-2019 22:32:52.372 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
18-Sep-2019 22:32:52.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
18-Sep-2019 22:32:52.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Transaction already in queue - removed original
18-Sep-2019 22:32:52.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added 1559 to queue - size 46
18-Sep-2019 22:32:52.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.372 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling initialised at 86400 seconds - start in 1500 milliseconds.
18-Sep-2019 22:32:52.484 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 C0 01 00 14 3E 
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=192, payload=C0 01 00 14 
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=192, payload=C0 01 00 14 
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: null
18-Sep-2019 22:32:52.485 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=192, payload=C0 01 00 14 
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.485 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 C0 00 00 15 3E 
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=192, payload=C0 00 00 15 
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=192, payload=C0 00 00 15 
18-Sep-2019 22:32:52.485 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
18-Sep-2019 22:32:52.486 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
18-Sep-2019 22:32:52.486 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: null
18-Sep-2019 22:32:52.486 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=192, payload=C0 00 00 15 
18-Sep-2019 22:32:52.486 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.486 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
18-Sep-2019 22:32:52.573 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
18-Sep-2019 22:32:52.574 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0E 03 26 01 00 25 C5 2C 
18-Sep-2019 22:32:52.574 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 0A 00 13 0E 03 26 01 00 25 C5 2C 
18-Sep-2019 22:32:52.574 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
18-Sep-2019 22:32:52.574 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1541: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 197
18-Sep-2019 22:32:52.575 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18-Sep-2019 22:32:52.575 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.575 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 1541: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 197
18-Sep-2019 22:32:52.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
18-Sep-2019 22:32:52.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.581 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
18-Sep-2019 22:32:52.581 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
18-Sep-2019 22:32:52.581 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
18-Sep-2019 22:32:52.582 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 1541: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 197
18-Sep-2019 22:32:52.582 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18-Sep-2019 22:32:52.582 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 1541: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 197
18-Sep-2019 22:32:52.582 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
18-Sep-2019 22:32:52.582 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 14: sentData successfully placed on stack.
18-Sep-2019 22:32:52.582 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 1541: Advanced to WAIT_REQUEST
18-Sep-2019 22:32:52.583 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 14: TID 1541: Transaction not completed
18-Sep-2019 22:32:52.583 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.583 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.619 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 C5 00 00 04 2A 
18-Sep-2019 22:32:52.619 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=197, payload=C5 00 00 04 
18-Sep-2019 22:32:52.620 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=197, payload=C5 00 00 04 
18-Sep-2019 22:32:52.620 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 1541: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 197
18-Sep-2019 22:32:52.620 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18-Sep-2019 22:32:52.620 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 1541: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 197
18-Sep-2019 22:32:52.620 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 1541: (Callback 197)
18-Sep-2019 22:32:52.621 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
18-Sep-2019 22:32:52.621 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 1541: callback 197
18-Sep-2019 22:32:52.621 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=197, payload=C5 00 00 04 
18-Sep-2019 22:32:52.621 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 14: SendData Request. CallBack ID = 197, Status = Transmission complete and ACK received(0)
18-Sep-2019 22:32:52.621 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 14: resetResendCount initComplete=true isDead=false
18-Sep-2019 22:32:52.621 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 1541: Transaction COMPLETED
18-Sep-2019 22:32:52.621 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 14: Response processed after 47ms
18-Sep-2019 22:32:52.622 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 14: TID 1541: Transaction completed
18-Sep-2019 22:32:52.622 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 14: notifyTransactionResponse TID:1541 DONE
18-Sep-2019 22:32:52.622 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
18-Sep-2019 22:32:52.622 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.622 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
18-Sep-2019 22:32:52.623 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1C 03 25 01 FF 25 C6 C1 
18-Sep-2019 22:32:52.623 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 28: Sending REQUEST Message = 01 0A 00 13 1C 03 25 01 FF 25 C6 C1 
18-Sep-2019 22:32:52.623 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
18-Sep-2019 22:32:52.623 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1543: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 198
18-Sep-2019 22:32:52.624 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18-Sep-2019 22:32:52.625 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.625 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18-Sep-2019 22:32:52.625 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 1543: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 198
18-Sep-2019 22:32:52.625 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
18-Sep-2019 22:32:52.625 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.625 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.630 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
18-Sep-2019 22:32:52.630 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
18-Sep-2019 22:32:52.631 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
18-Sep-2019 22:32:52.631 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 1543: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 198
18-Sep-2019 22:32:52.631 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18-Sep-2019 22:32:52.632 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 1543: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 198
18-Sep-2019 22:32:52.632 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
18-Sep-2019 22:32:52.632 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 28: sentData successfully placed on stack.
18-Sep-2019 22:32:52.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 1543: Advanced to WAIT_REQUEST
18-Sep-2019 22:32:52.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 28: TID 1543: Transaction not completed
18-Sep-2019 22:32:52.634 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.634 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
18-Sep-2019 22:32:52.746 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 C6 00 00 0C 21 
18-Sep-2019 22:32:52.746 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=198, payload=C6 00 00 0C 
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=198, payload=C6 00 00 0C 
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 1543: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 198
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 1543: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 198
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 1543: (Callback 198)
18-Sep-2019 22:32:52.748 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 1543: callback 198
18-Sep-2019 22:32:52.748 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=198, payload=C6 00 00 0C 
18-Sep-2019 22:32:52.748 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 28: SendData Request. CallBack ID = 198, Status = Transmission complete and ACK received(0)
18-Sep-2019 22:32:52.748 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 28: resetResendCount initComplete=true isDead=false
18-Sep-2019 22:32:52.748 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 1543: Transaction COMPLETED
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 28: Response processed after 125ms
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 28: TID 1543: Transaction completed
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 28: notifyTransactionResponse TID:1543 DONE
18-Sep-2019 22:32:52.748 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 28: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
18-Sep-2019 22:32:52.748 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 25 01 00 25 C7 29 
18-Sep-2019 22:32:52.748 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 25 01 00 25 C7 29 
18-Sep-2019 22:32:52.748 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
18-Sep-2019 22:32:52.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1545: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 199
18-Sep-2019 22:32:52.749 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

While waiting for Chris, you may want to try the log viewer that Chris uses.

https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

Ok, this issue is only a startup issue. I think it’s also been fixed, although I could be wrong if you are using M3 and it’s still happening?

Yes M3, sorry not sure what you mean by startup? it happens for hours

Just to be clear, what are you talking about? What “happens for hours”?

(and my next question will be to ensure that you have a log that shows what ever the problem is :slight_smile: ).

1 Like

Thanks for your patience Chris, the delay in commands going to the devices is what I was referring to - If I send a dim to 10% command via basic UI or a rule, it may take minutes before the light changes, but it does eventually get there. you said it was a startup issue, so I assumed that meant when OH starts up. I have been resarting my OH as part of the troubleshooting and even well after it has started up “hours” the behaviour is still there.
Sometimes the devices respond immediately - some are this morning.

My logs are set to INFO but the odd thing is there is no log lines in there for over 7 hours and only one over night but perhaps this is normal at INFO level.

Should I leave DEBUG on for a while and provice this log.

INFO based log overnight showing the debug to info levels

18-Sep-2019 22:37:29.530 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 25: resetResendCount initComplete=true isDead=false
18-Sep-2019 22:37:29.530 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
18-Sep-2019 22:37:29.530 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported
18-Sep-2019 22:37:29.530 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_BASIC V1 BASIC_SET
18-Sep-2019 22:37:29.530 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 25: Basic report, value = 0
18-Sep-2019 22:37:29.530 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
18-Sep-2019 22:37:29.530 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0
18-Sep-2019 22:37:29.531 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:zwavecontroller:node25:sensor_binary to OFF [OnOffType]
18-Sep-2019 22:37:29.531 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.
18-Sep-2019 22:37:29.531 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7ffd78.
18-Sep-2019 22:37:29.531 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18-Sep-2019 22:37:29.531 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
18-Sep-2019 22:37:29.531 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18-Sep-2019 22:37:29.531 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
19-Sep-2019 02:37:13.071 [ERROR] [protocol.serialmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.

You can also use the viewer to see if anything looks out of place.

https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

Well, this statement was based on what I thought that the problem was what you mentioned earlier :confounded:

This issue is a startup issue. It looks like now there’s a different issue though if I understand correctly? I can’t find any of these errors in your log t all.

If you are having delays in the network, that is obviously not a startup issue - that probably is caused if there are some timeouts in your system. Possibly a device is not responding occasionally. A much longer log would be needed to see this.

Further evaluation - it seems to be quite intermittent, sometimes normal fast response, other times slow - perhaps there is also an issue with my setup and things are restarting causing the startup issue to “reappear”
Chris, I dont want to waste your time, I will keep experimenting and see whether I can find anything else.

1 Like

This is very indicative of the issue I mentioned where a device might not be responding well. It will vary if the device is at the edge of range - sometimes it will work, other times not. This leads to commands being delayed sometimes, and it also depends on what other things are happening within the network (ie it won’t happen if that device is not doing anything).

I would really suggest to check the debug logs as this should be quite easy to see.

OK I am logging and so far everything is respondong. I havent had any changes to my zwave environment other than M3 install.
Other thing of interest it seems a lot of the association groups are blank in paperui - I had this problem ages ago Im going back and resetting these. I didnt have to rediscover going from m2 to m3 did I?

If you are using the Chrome browser clear your browser cache. I have had Paper UI breakage after upgrading that was due to that.

I try to add Fibaro smart implant FGBS-222 with the Z-Wave Binding installed from Paper UI (2.4.0) but it is found as an unknown device.
How can I solve the problem?
Can you tell me step by step how to proceed with a possible update if necessary?
Thanks.