OH2 Z-Wave refactoring and testing... and SECURITY

rgerrans · October 15, 2017, 8:52pm

With the newest zwave binding I’m getting the following errors showing up again. If I move back to last weeks build everything starts fine:

2017-10-15 14:43:00.703 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zwave-2.2.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zwave [10]
  Unresolved requirement: Import-Package: com.google.common.collect

	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:1253) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1225) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:512) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:361) [8:org.apache.felix.fileinstall:3.6.0]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:312) [8:org.apache.felix.fileinstall:3.6.0]

stevenazari · October 15, 2017, 8:57pm

Hi Matt,
Sorry I’m not helping but my suggestion was that there was no wake up request after sleep… there was an alive log though… so I’m likely wrong (I’m an openhab noob).

I think further up the chain of this thread I read that battery operated items also need to be added securely… I will search now

That’s a missing dependancy error?

sihui · October 15, 2017, 9:06pm

You don’t HAVE TO to add those devices securely. Just the locks (which solely have the secure “channels”).
The development version of the zwave binding is able to deal with secure and unsecure devices.

stevenazari · October 15, 2017, 9:16pm

ah my bad, back to the drawing board then…

rgerrans · October 16, 2017, 12:47pm

Correct, but it only appears with the latest version and not the one from a few weeks ago. @shawnmix had the same issue a while back with a different build but I never saw a specific resolution. I also can’t find any specific bindings referenced anyplace which contain the dependencies. So was wanting to see if anyone else was seeing the same issue or if it was specific to my setup.

Thanks.

rgerrans · October 16, 2017, 12:49pm

Did you figure out a specific fix for the com.google.common.collect missing dependency?

dezito · October 16, 2017, 2:37pm

I have the same problem sometimes, do the following:
ssh openhab@localhost -p8101
password: habopen
bundle:list (locate the Z-Wave plugin mine was number 10)
bundle:uninstall 10
logout
goto the addon folder and remove the jar plugin file
download the plugin again to the folder and the plugin should launch correctly no need the restart of openhab

rgerrans · October 17, 2017, 2:22am

That solved it, thanks!!

Matt77 · October 20, 2017, 8:02pm

did anyone get the Fibaro Door/Window sensor (FGK101 Door Opening Sensor) to work?
I’m getting the battery level but that’s all. no open/close status.

chris · October 20, 2017, 8:29pm

Well, it was working for me some time back. Maybe it’s broken now for some reason, but I would be surprised .

Seaside · October 20, 2017, 8:46pm

I have it working. Included two of them the other week. The channels have changed though from what they used to be 6 months back.

Regards s

Matt77 · October 21, 2017, 11:44am

HI, hmm wondering what im doing wrong then.
already excluded and re-included it.

but i have strange things in my log, including entries like “Node dead” or “Is currently marked as failed by the controller!”.
but with the non Security binding its working.
i also noticed that all my battery devices are showing as " node is not comunicating with controller" in habmin. haven’t hat that with the “non security” binding.

2017-10-21 15:38:21.029 [hingStatusInfoChangedEvent] - 'zwave:device:15f1ee0619b:node31' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
==> /var/log/openhab2/openhab.log <==
2017-10-21 15:38:21.035 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-21 15:38:21.039 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 31: COMMAND_CLASS_MULTI_CHANNEL not found
2017-10-21 15:38:21.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:21.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-21 15:38:21.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-21 15:38:21.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-10-21 15:38:49.387 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 26: Requesting IsFailedNode status from controller.
2017-10-21 15:38:49.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@179171e
2017-10-21 15:38:49.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-10-21 15:38:49.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-10-21 15:38:49.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-21 15:38:49.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-21 15:38:49.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-10-21 15:38:49.415 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 1A 83 
2017-10-21 15:38:49.419 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 1A 83 
2017-10-21 15:38:49.423 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-10-21 15:38:49.425 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-10-21 15:38:49.427 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: Transaction Start type IsFailedNodeID 
2017-10-21 15:38:49.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-10-21 15:38:49.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-10-21 15:38:49.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-10-21 15:38:49.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 2000ms
2017-10-21 15:38:49.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.446 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1988ms
2017-10-21 15:38:49.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-10-21 15:38:49.459 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 31: Requesting IsFailedNode status from controller.
2017-10-21 15:38:49.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:49.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@eae6b
2017-10-21 15:38:49.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-10-21 15:38:49.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-10-21 15:38:49.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-10-21 15:38:49.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-10-21 15:38:49.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-10-21 15:38:49.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-10-21 15:38:49.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1961ms
2017-10-21 15:38:49.480 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
2017-10-21 15:38:49.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.485 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-21 15:38:49.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1949ms
2017-10-21 15:38:49.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-10-21 15:38:49.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 16469: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.503 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.505 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 26: Is currently marked as failed by the controller!
2017-10-21 15:38:49.506 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: Transaction COMPLETED
2017-10-21 15:38:49.508 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance ST: DONE
2017-10-21 15:38:49.509 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance WT: null {}
2017-10-21 15:38:49.511 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance RX: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.512 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16469: TransactionAdvance TO: DONE
2017-10-21 15:38:49.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 87ms
2017-10-21 15:38:49.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 16469: Transaction completed
2017-10-21 15:38:49.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:16469 DONE
2017-10-21 15:38:49.519 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-10-21 15:38:49.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 16469: Transaction event listener: DONE: DONE -> 
2017-10-21 15:38:49.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:49.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-21 15:38:49.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-21 15:38:49.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
2017-10-21 15:38:49.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-10-21 15:38:49.527 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 1F 86 
2017-10-21 15:38:49.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 16469 -- 
2017-10-21 15:38:49.529 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 1F 86 
2017-10-21 15:38:49.529 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init response (0) COMPLETE
2017-10-21 15:38:49.531 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-10-21 15:38:49.531 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init transaction completed with response COMPLETE
2017-10-21 15:38:49.532 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16470: Transaction Start type IsFailedNodeID 
2017-10-21 15:38:49.533 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-10-21 15:38:49.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-10-21 15:38:49.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-10-21 15:38:49.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-10-21 15:38:49.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.538 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
2017-10-21 15:38:49.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1998ms
2017-10-21 15:38:49.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.545 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-21 15:38:49.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1993ms
2017-10-21 15:38:49.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-21 15:38:49.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-10-21 15:38:49.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-21 15:38:49.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-10-21 15:38:49.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-10-21 15:38:49.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-21 15:38:49.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Oct 21 15:38:51 GST 2017 - 1980ms
2017-10-21 15:38:49.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-10-21 15:38:49.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 16470: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-21 15:38:49.567 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-21 15:38:49.568 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 31: Is currently marked as failed by the controller!
2017-10-21 15:38:49.570 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
2017-10-21 15:38:49.572 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2017-10-21 15:38:49.573 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: Setting OFFLINE

Mike_Bagdanoff · October 22, 2017, 3:33pm

Just had a device die with a completely dead battery, though the logs were showing 100% like most other devices on my system. It was an aeotec dry contact sensor.

chris · October 22, 2017, 3:40pm

I’m not sure what response you’re expecting? If the device is reporting 100%, then the binding can’t do much about that . Or do you mean the device was reporting a low number but the binding was still saying 100%?

Matt77 · October 23, 2017, 3:56am

[quote=“Matt77, post:1848, topic:21653, full:true”]

HI, hmm wondering what im doing wrong then.
already excluded and re-included it.

but i have strange things in my log, including entries like “Node dead” or “Is currently marked as failed by the controller!”.
but with the non Security binding its working.
i also noticed that all my battery devices are showing as " node is not comunicating with controller" in habmin. haven’t hat that with the “non security” binding.

Hi @chris, do you have any suggestion for me what the problem could be with the door/window sensor?
after some additional “Heal” for those two battery devices they at least showing to be working fine in HABmin, however the door/window is still not reporting any open/close state at all.

i tried again with the binding included in the snapshot release of OH2 and there everything is fine.

i re-included the node and this is what i can see if i open/close it"

2017-10-23 23:32:42.637 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 13 00 04 00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 32 
2017-10-23 23:32:42.646 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-23 23:32:42.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-10-23 23:32:42.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Application Command Request (ALIVE:DONE)
2017-10-23 23:32:42.672 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: resetResendCount initComplete=true isDead=false
2017-10-23 23:32:42.676 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-23 23:32:42.681 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: COMMAND_CLASS_MULTI_CHANNEL not found
2017-10-23 23:32:42.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-23 23:32:42.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-23 23:32:42.694 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.702 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.711 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.717 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-23 23:32:42.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing

chris · October 23, 2017, 8:23pm

This means that the controller thinks the device is no communicating. There was a long discussion on this earlier (somewhere!) in this thread. I don’t really know why the controller sets this state on devices that are working - according to the docs, it shouldn’t. This version of the binding uses the controller status to decide if the device is dead or not rather than doing something internally - this is why the older version works.

vossivossi · October 23, 2017, 9:11pm

Yes, there was a discussion here on this. But I remember that you planned to change this as the controller status seemed not to be reliable. Do you still plan to do this?
At the moment my “workaround” for main powered nodes (230V, no battery devices) that are marked as “dead” is to change an unimportant configuration parameter in Habmin. In this case the binding apparently seems to ignore the dead status, sends the parameter and gets a confirmation. Immediately the system starts the mesh update for the node and it works again. It is silly that these 2 clicks immediately “cure” each main powered node while the binding will show it for hours or days as “dead”.
However, for battery powered devices this does not work. I have a couple of sensative strips door/window sensors which are dead since more than several months (according to the binding and also according to the last time stamp of the xml-File in the Z-Wave folder). However, they report their status several times a day reliably to OH.
So I would like a solution that does not ignore these facts but states a “real” status of the devices (as in former times, eg. OH1, OH2 etc.)

chris · October 23, 2017, 9:12pm

Yes - clearly the current system doesn’t work well . I will try and look at this soon.

chris · October 23, 2017, 9:19pm

I’m not sure I understand this? What is the “Real” status? The theory is that the controller has the best information, and therefore it knows the “real” status better than anyone else. The binding can try to evaluate the status, but I’m not sure what you refer to as a “real” status? I guess you are asking to ignore the controller? Either way, we have to ignore some “facts”?

Can you explain what you mean? (sorry for my lack of understanding with this).

Matt77 · October 24, 2017, 4:12am

as per my previous post it seems that the controller is now not thinking any more the Node would be dead and as it looks like i receive messages from the node when the contact gets opened/closed.

2017-10-23 23:32:42.637 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 13 00 04 00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 32 
2017-10-23 23:32:42.646 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-23 23:32:42.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-10-23 23:32:42.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Application Command Request (ALIVE:DONE)
2017-10-23 23:32:42.672 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: resetResendCount initComplete=true isDead=false
2017-10-23 23:32:42.676 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-23 23:32:42.681 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: COMMAND_CLASS_MULTI_CHANNEL not found
2017-10-23 23:32:42.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-23 23:32:42.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-23 23:32:42.694 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.702 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.711 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.717 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-23 23:32:42.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing

“binary sensor” and “battery level” are receiving status changes/values but not the important one “Door Sensor”