And it generates an XML? This is really strange. I just checked the database exports, and there is nothing in the XML that is used by the protocol layer when initialising this, so I suspect there is something else at play. Maybe you’re not letting it initialise properly?
Sorry - I did not see that. Clearly there is something wrong in your system if there is nothing showing in the debug log.
No - just enable debug logging in the standard way with the set:log command.
Please don’t get me wrong. I appreciate the quick updates VERY MUCH and this was no complaint about the avaialability of updates at all. Thank you very much for all your efforts!
I was just answering to the post of @5iver who told me to install the new binding instead of reporting errors of a 30 hours old binding (which apparently was already outdated). So my point is that I consider it useful to report errors which only occur after a long time usage even if there is already a new binding version available. Because maybe they are not yet solved in the new version. And from the last posts in this thread I assume that the Java exceptions are not yet resolved all.
Just tried to load the latest snapshot… This happened.
2018-07-26 22:07:19.559 [WARN ] [org.apache.felix.fileinstall ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zwave-2.4.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zwave [211]
Another singleton bundle selected: osgi.identity; osgi.identity=“org.openhab.binding.zwave”; type=“osgi.bundle”; version:Version=“2.3.0”; singleton:=“true”
at org.eclipse.osgi.container.Module.start(Module.java:444) [?:?]
at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) [?:?]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [9:org.apache.felix.fileinstall:3.6.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [9:org.apache.felix.fileinstall:3.6.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1221) [9:org.apache.felix.fileinstall:3.6.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:515) [9:org.apache.felix.fileinstall:3.6.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [9:org.apache.felix.fileinstall:3.6.4]
at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [9:org.apache.felix.fileinstall:3.6.4]
Any clue what’s wrong??
This means that you have two copies of the zwave binding loaded. Ensure that you uninstall the first binding before loading the development binding. Use the Karaf console to list the running bundles, and if that doesn’t work, use the uninstall command to remove the old binding.
Thanks so much!
New problem… One of my devices, a ZEN06 Smart Plug with 2 USB ports, has a serious problem. I click the switch to turn it on in OpenHab and it immediately turns on, but my openhab.log shows this over and over, every 5 seconds:
2018-07-27 01:17:30.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 C5 01 2D
2018-07-27 01:17:30.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=197, payload=C5 01
2018-07-27 01:17:30.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=1, callback=197, payload=C5 01
2018-07-27 01:17:30.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=197, payload=C5 01
2018-07-27 01:17:30.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 247: [WAIT_REQUEST] requiresResponse=true callback: 197
2018-07-27 01:17:30.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-27 01:17:30.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 247: [WAIT_REQUEST] requiresResponse=true callback: 197
2018-07-27 01:17:30.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 247: (Callback 197)
2018-07-27 01:17:30.020 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-27 01:17:30.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 247: callback 197
2018-07-27 01:17:30.020 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=197, payload=C5 01
2018-07-27 01:17:30.021 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 197, Status = Transmission complete, no ACK received(1)
2018-07-27 01:17:30.021 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 247: Transaction CANCELLED
2018-07-27 01:17:30.021 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-27 01:17:30.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Retry count exceeded. Discarding message: TID 247: [CANCELLED] requiresResponse=true callback: 197
2018-07-27 01:17:30.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 247: Transaction completed
2018-07-27 01:17:30.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:247 CANCELLED
2018-07-27 01:17:30.022 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-27 01:17:30.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-27 01:17:30.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-27 01:17:30.022 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 25 02 25 C6 20
2018-07-27 01:17:30.023 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 25 02 25 C6 20
2018-07-27 01:17:30.023 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-27 01:17:30.023 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 252: Transaction Start type SendData
2018-07-27 01:17:30.024 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-27 01:17:30.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:17:30.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:17:30.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:17:30.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 252: [WAIT_RESPONSE] requiresResponse=true callback: 198
2018-07-27 01:17:30.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-27 01:17:30.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-27 01:17:30.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-27 01:17:30.034 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-07-27 01:17:30.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:17:30.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:17:30.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:17:30.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 252: [WAIT_RESPONSE] requiresResponse=true callback: 198
2018-07-27 01:17:30.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-27 01:17:30.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 252: [WAIT_RESPONSE] requiresResponse=true callback: 198
2018-07-27 01:17:30.036 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:17:30.037 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
2018-07-27 01:17:30.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 252: Advanced to WAIT_REQUEST
2018-07-27 01:17:30.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 252: Transaction not completed
2018-07-27 01:17:30.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-27 01:17:30.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
This in itself is a serious problem, but there’s a bigger one… So long as this is going on, OpenHab can’t control ANY Z-wave device on the network! It’s completely blocked. I tried to “heal” the device… Now the Z-Wave network is blocked until I restart the Z-Wave binding:
2018-07-27 01:25:42.389 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: WakeupTimerTask 5 Messages waiting, state PING
2018-07-27 01:25:44.889 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: WakeupTimerTask 5 Messages waiting, state PING
2018-07-27 01:25:46.016 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 1F 01 F7
2018-07-27 01:25:46.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=31, payload=1F 01
2018-07-27 01:25:46.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=1, callback=31, payload=1F 01
2018-07-27 01:25:46.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=31, payload=1F 01
2018-07-27 01:25:46.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 275: [WAIT_REQUEST] requiresResponse=true callback: 31
2018-07-27 01:25:46.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-27 01:25:46.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 275: [WAIT_REQUEST] requiresResponse=true callback: 31
2018-07-27 01:25:46.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 275: (Callback 31)
2018-07-27 01:25:46.017 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-27 01:25:46.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 275: callback 31
2018-07-27 01:25:46.018 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=31, payload=1F 01
2018-07-27 01:25:46.018 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 31, Status = Transmission complete, no ACK received(1)
2018-07-27 01:25:46.018 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 275: Transaction CANCELLED
2018-07-27 01:25:46.018 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-27 01:25:46.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: CANCEL while sending message. Requeueing - 2 attempts left!
2018-07-27 01:25:46.018 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 275: Transaction RESET with 2 retries remaining.
2018-07-27 01:25:46.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2018-07-27 01:25:46.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-27 01:25:46.019 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 03 03 70 05 AE 25 20 38
2018-07-27 01:25:46.019 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 70 05 AE 25 20 38
2018-07-27 01:25:46.019 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-27 01:25:46.020 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 275: Transaction Start type SendData
2018-07-27 01:25:46.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 275: Transaction not completed
2018-07-27 01:25:46.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-27 01:25:46.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-27 01:25:46.021 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-27 01:25:46.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:25:46.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:25:46.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:25:46.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 275: [WAIT_RESPONSE] requiresResponse=true callback: 32
2018-07-27 01:25:46.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-27 01:25:46.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-27 01:25:46.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-27 01:25:46.030 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-07-27 01:25:46.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:25:46.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:25:46.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:25:46.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 275: [WAIT_RESPONSE] requiresResponse=true callback: 32
2018-07-27 01:25:46.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-27 01:25:46.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 275: [WAIT_RESPONSE] requiresResponse=true callback: 32
2018-07-27 01:25:46.032 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-07-27 01:25:46.032 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
2018-07-27 01:25:46.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 275: Advanced to WAIT_REQUEST
2018-07-27 01:25:46.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 275: Transaction not completed
2018-07-27 01:25:46.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-27 01:25:46.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
A single problem device shouldn’t be able to completely block the binding.
Thanks in advance for your help in fixing this.
EDIT: Spoke too soon… Restarting the binding does this:
2018-07-27 01:28:45.147 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@58897966
2018-07-27 01:28:45.534 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 312: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2018-07-27 01:28:45.535 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 312: Transaction is current transaction, so clearing!!!!!
2018-07-27 01:28:45.535 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 312: Transaction CANCELLED
2018-07-27 01:28:45.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:312 CANCELLED
2018-07-27 01:28:45.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-27 01:28:45.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 312: Transaction event listener: DONE: CANCELLED ->
2018-07-27 01:28:45.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- TIMEOUT_WAITING_FOR_CONTROLLER
2018-07-27 01:28:45.536 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 02 B8
2018-07-27 01:28:45.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 312 --
2018-07-27 01:28:45.536 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@5b0bcf81
2018-07-27 01:28:45.536 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 02 B8
2018-07-27 01:28:45.537 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-27 01:28:45.537 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 314: Transaction Start type IdentifyNode
2018-07-27 01:28:45.538 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-27 01:28:45.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 16<>112 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:28:45.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:28:45.539 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 01 04 11 01 EC
2018-07-27 01:28:45.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 17<>111 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 11 01
2018-07-27 01:28:45.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 11 01
2018-07-27 01:28:46.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@5f4bdacf
2018-07-27 01:28:46.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2018-07-27 01:28:46.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-27 01:28:46.680 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 03 98
2018-07-27 01:28:46.681 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 04 00 60 03 98
2018-07-27 01:28:46.681 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 315: Transaction Start type RequestNodeInfo
2018-07-27 01:28:47.538 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 314: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2018-07-27 01:28:47.538 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 314: Transaction is current transaction, so clearing!!!!!
2018-07-27 01:28:47.538 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 314: Transaction CANCELLED
2018-07-27 01:28:47.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:314 CANCELLED
2018-07-27 01:28:47.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-27 01:28:47.540 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9
2018-07-27 01:28:47.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 314: Transaction event listener: DONE: CANCELLED ->
2018-07-27 01:28:47.540 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9
2018-07-27 01:28:47.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- TIMEOUT_WAITING_FOR_CONTROLLER
2018-07-27 01:28:47.541 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-27 01:28:47.542 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 303: Transaction Start type GetControllerCapabilities
2018-07-27 01:28:47.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 314 --
2018-07-27 01:28:47.543 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@3fdc1486
2018-07-27 01:28:47.543 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-27 01:28:47.544 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 18<>110 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:28:47.544 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-27 01:28:47.544 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 1C E3
2018-07-27 01:28:47.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 19<>109 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C
2018-07-27 01:28:47.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C
2018-07-27 01:28:48.682 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 3: TID 315: Timeout at state WAIT_RESPONSE. 3 retries remaining.
The only way to restore my network to normal operation was to remove the device.
The binding is trying to read some data from the device, but it does not appear to be responding. There is no ACK from the device at all, so probably it is out of range - at least we can say it doesn’t respond (based on this log at least).
That should not be the case. This command is a GET request which has a lower priority than a SET request.
Can you describe the problem?
Really it’s hard to understand your problem with such a short log excerpts - it is MUCH better to provide a long log as it’s impossible to see what is happening like this. You say for example that the whole binding is blocked, but I can’t see this - you only provide a single transaction which has no context.
I have a device on my network. The ZEN06 switch mentioned above. The signal is great, works fine on the stock 2.3 Z-Wave binding.
In the OpenHAB UI, there’s a slider switch to control the physical ZEN06 switch. When I click the slider switch in OpenHAB to turn the physical ZEN06 switch on, the switch turns on, and the Z-Wave binding gets stuck in a loop trying to close out the transaction (See pasted log 1 above).
While this is occurring, OpenHAB can’t control any other Z-Wave devices. Using other parts of the UI that interact with Z-Wave devices has no effect on the devices. Dimmers can’t be dimmed, switches can’t be powered.
I’d love to send you the log, however, not only does this forum not allow .log files to be attached, but as a new user I’m not even allowed to attach files… And dumping 1.5MB of text inline with this post doesn’t seem like a nice thing to do.
I guess you are referring to the above point where I said that no ack is received and this could be because the device is out of range? How do you know the “signal is great”? This information is not provided anywhere (at least not in OH). For sure, I can say that no response is received in the log you provided. Maybe this is just a one off - I don’t know and this is why I ask for more logs.
Unfortunately, without more logs, I can’t see this. Sorry, but a single entry doesn’t show that there is a loop, and since there is nothing wrong with the log you provided, it’s hard really to comment.
Without the logs I can’t comment on anything - sorry. Most people provide logs using their favourite dumping ground (eg dropbox), and then linking to the logs here.
Thanks for the suggestion Chris. Here’s the log.
I know the signal is fine for three reasons. First, the device is less than 20 feet from the Z-Wave gateway. Second, this device has internal signal reporting. Third, the device works flawlessly with the existing Z-Wave binding.
Regardless of the device’s signal strength, a single device should not prevent the binding from interacting with other Z-Wave devices, which is what is happening here.
I really appreciate your help here and really, really appreciate all the hard work you have put in to help make Z-Wave a reality for the OpenHab community. Thanks!
Sorry, but this doesn’t mean that the link works.
To this, I agree, but the binding should not do this, and I’ve asked for a log to show what is happening. I’m really sorry if it seems like I’m being difficult, but as I said earlier, a single transaction is really of limited use - I need to see a longer log to see what is happening and without this it’s really difficult to help (again, I apologise).
Thanks.
I attached a link to the log to my last post. Did you not see it? Here it is again.
Hi, is there any change with the fibaro FGK101 until the last month? My last update was around one month ago, there the sensor works without any problem. Also the installed DS18b20 will send temperatur Data. Now i update early this week to the last snapshot. With this i must reinklude the devices. Now i have in the /var/lib/openhab2/zwave/ folder xml Files with „network_deexxx__node_xx.xml“ and no more „nodexx.xml“. The most devices will work, however the KGK101 not correctly. 
HABmin shows firmeware 2.5 and i have only the channels Binary Sensor, Batterieladung and Smoke alarm.
I don’t see anything obviously wrong in your log. Messages to other devices other than node 3 are being sent, so the binding is not blocking on this node being dead. From what I can see in the log, node 2 receives some commands, and they are sent immediately to the device and are ACKed and work fine. Node 3 is clearly not responding as the controller is returning from the transaction saying it did not receive an ACK - from what I can tell this is the case for every command that is sent, so clearly there is something wrong with this device.
Hi, with the „old“ binding the sensor Reporte Open Close, now its a switch with On Off - why?
Probably the answer is that the channel type has changed, although both the master and development binding use the same database, so it will not change between versions.
I have remove the Device and re include the device, now i have switches instead of contacts and no temperature transmission anymore. 
Parameter 15 show “DS18B20 is working properly”
It looks like a new version was added specifically for 2.5. Please provide the XML file OH created for your device.
Thist is the old one: node17.xml (12.0 KB)
And This is the new one: network_dee83f0f__node_40.xml (17.1 KB)
Well, for one thing, the database doesn’t have a temperature channel. Can you see the device reporting temperature in the debug log?