Ok, that is probably the cause - this is at the time the initialisation stopped. I’ll take a look at this…
Thanks.
I made an error with the database when I added the extra feature yesterday and added the old database file, not the one that works with this version of the binding 
. I’ve just updated this - let’s see if it’s any better - sorry for that…
1 Like
Node35.log
initialized … w empty association groups, but did let me to save them.
00:00:00-00:00:31 fires events only on one binary channel
00:02:30-00:03:20 fires events only on the other binary channel
Please try this version.
There are so many different implementations of this multi-channel - I want to see if this helps at all and then I’ll have to rethink how best to handle it.
it looks very … zigbee 
reading my mind. at least, not worse:slight_smile:
Node2.7z this time.
I’m off for a little nap, available for next set in some 6-7hours. Thank You a lot for helping to fight it!
Yep - time for bed… I have ordered up one of these so I can test it - I’ll take a look over the weekend if it’s here by then (should arrive on Friday).
1 Like
@chris I’ve just installed the latest development binding, but seem to be having issues with a Qubino ZMNHBD (firmware is v1.1) dual relay - probably related to the multi-channel problem you’ve been discussing above?
On both the stable and snapshot releases, the relay works fine. However, with the development build, the relays simply stop responding to openHAB commands (physical switch works fine). The issue is there regardless of whether I send a command to the combined switch_binary channel, or whether I send commands to the individual switch channels.
If you see the attached log for example, at 12:53pm, I sent an OFF command to the combined switch channel (lights are physically on). Habmin shows that the switch is off, but the physical lights remain on.
I’ve tried deleting/adding to OH2 (and of course deleted/re-added all zwave devices when switching between development and snapshot builds), but not sure what else to try.
I had the same issue with the previous development build as well, and so had to revert to the snapshot build at that time.
UPDATE: If it helps, it seems that following a restart of openHAB, the same Qubino relays respond correctly to openHAB commands. They then stop responding after openHAB has been running for some time (I haven’t managed to determine quite when they stop). Restarting the zwave bundle does not make a difference - a restart of openHAB is required.
UPDATE 2: Since the last restart a few hours ago, the device seems to be working normally till now. Not sure what has changed, and whether it was just that the system needed a few restarts.
zwave.xml (3.4 KB)
Sorry for the late reply.
There is nothing been logged in logs as well.
let me tell you bit about my setup (I am not sure this is the right thread, please point me to the right one in that case)
I got a one Yale Real Living Touchscreen Deadbolt, Aeon Labs Smart Switch and Z-Wave USB Stick on a raspberry pi running these.
I have set up one item for lock door channel and one item for switch binary in switch and 2 battery level items.
Also I got one item linked to serial_ack in usb stick.
I can change lock status, plug state all work fine. But Issue comes when I unlock the door manually it will not update on openhab. In logs i can see serial_ack increases by 1 every time I lock/unlock. However don’t see any events or logs related to lock item nor the state will not change accordingly for manual changes. Is this something only I am experiencing or is there any setup to fix this ?
Cheers
R.
If every time you lock or unlock, there’s a ZWave event, then I would think that it must be related to the lock. I need to see what this is - can you provide a debug log showing this please?
@chris thank you for the reply.
Sorry New users cannot upload files.
Followings are the trace info that comes up when I do a manual unlock. However, item attached to that does not show the right state
WHEN I MANUALLY UNLOCK THE DOOR
13:40:55.697 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:40:55.706 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 03 02 98 40 2A
13:40:55.709 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 04 00 03 02 98 40 2A
13:40:55.711 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x2A
13:40:55.713 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:40:55.717 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Message payload = 00 03 02 98 40
13:40:55.720 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:40:55.723 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:40:55.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 02 98 40
13:40:55.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 02 98 40
13:40:55.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 02 98 40
13:40:55.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
13:40:55.747 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
13:40:55.750 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:40:55.753 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
13:40:55.755 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY check internal
13:40:55.758 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_GET
13:40:55.761 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1
13:40:55.764 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
13:40:55.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added to secure queue - size 1
13:40:55.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
13:40:55.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@a39892.
13:40:55.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:40:55.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:40:55.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:40:55.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
13:40:55.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue
13:40:55.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
13:40:55.791 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request (0x00)
13:40:55.793 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x5B
13:40:55.796 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 03 0A 98 80 F7 FF 41 C6 E7 F7 DA 46 25 91 5B
13:40:55.799 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 11 00 13 03 0A 98 80 F7 FF 41 C6 E7 F7 DA 46 25 91 5B
13:40:55.801 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
13:40:55.803 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: Transaction Start type SendData
13:40:55.806 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:40:55.808 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:40:55.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:40:55.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:40:55.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 945: [WAIT_RESPONSE] requiresResponse=true callback: 145
13:40:55.817 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:40:55.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
13:40:55.821 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:40:55.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
13:40:55.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:40:55.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:40:57 NZDT 2017 - 2000ms
13:40:55.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 945: [WAIT_RESPONSE] requiresResponse=true callback: 145
13:40:55.833 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:40:55.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:40:55.842 [INFO ] [marthome.event.ItemStateChangedEvent] - Room_SerialControler_FramesAcknowledge_Label changed from 939 to 940
13:40:55.842 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xE8
13:40:55.853 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:40:55.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:40:57 NZDT 2017 - 1981ms
13:40:55.855 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:40:55.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:40:55.860 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:40:55.861 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:40:55.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 945: [WAIT_RESPONSE] requiresResponse=true callback: 145
13:40:55.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:40:55.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:40:55.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:40:55.867 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:40:55.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:40:55.871 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 91 00 00 02 78
13:40:55.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
13:40:55.873 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 91 00 00 02 78
13:40:55.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:40:55.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:40:55.876 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x78
13:40:55.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:40:57 NZDT 2017 - 1957ms
13:40:55.880 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:40:55.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:40:55.883 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 91 00 00 02
13:40:55.885 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 945: [WAIT_RESPONSE] requiresResponse=true callback: 145
13:40:55.886 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:40:55.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:40:55.890 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:40:55.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=145, payload=91 00 00 02
13:40:55.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 945: [WAIT_RESPONSE] requiresResponse=true callback: 145
13:40:55.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=145, payload=91 00 00 02
13:40:55.896 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:40:55.898 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:40:55.900 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 04 00 03 18 98 81 12 86 76 4E 39 F8 79 5B 2B C3 1B 9D 25 F7 C9 88 11 FB C1 B6 F4 46 7A
13:40:55.902 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:40:55.904 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 1E 00 04 00 03 18 98 81 12 86 76 4E 39 F8 79 5B 2B C3 1B 9D 25 F7 C9 88 11 FB C1 B6 F4 46 7A
13:40:55.905 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x7A
13:40:55.906 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:40:55.907 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:40:55.909 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Message payload = 00 03 18 98 81 12 86 76 4E 39 F8 79 5B 2B C3 1B 9D 25 F7 C9 88 11 FB C1 B6 F4 46
13:40:55.910 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:40:55.910 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:40:55.911 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance ST: WAIT_RESPONSE
13:40:55.912 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:40:55.919 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance WT: null {}
13:40:55.921 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:40:55.921 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 18 98 81 12 86 76 4E 39 F8 79 5B 2B C3 1B 9D 25 F7 C9 88 11 FB C1 B6 F4 46
13:40:55.922 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance TO: WAIT_REQUEST
13:40:55.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 945: Advanced to WAIT_REQUEST
13:40:55.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 18 98 81 12 86 76 4E 39 F8 79 5B 2B C3 1B 9D 25 F7 C9 88 11 FB C1 B6 F4 46
13:40:55.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 945: Transaction not completed
13:40:55.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=145, payload=91 00 00 02
13:40:55.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 945: [WAIT_REQUEST] requiresResponse=true callback: 145
13:40:55.929 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:40:55.930 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 945: [WAIT_REQUEST] requiresResponse=true callback: 145
13:40:55.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 945: (Callback 145)
13:40:55.932 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
13:40:55.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 945: callback 145
13:40:55.939 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=145, payload=91 00 00 02
13:40:55.940 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:40:55.942 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:40:55.946 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 145, Status = Transmission complete and ACK received(0)
13:40:55.947 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:40:55.949 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: Transaction COMPLETED
13:40:55.950 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance ST: DONE
13:40:55.951 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance WT: null {}
13:40:55.953 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=145, payload=91 00 00 02
13:40:55.954 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 945: TransactionAdvance TO: DONE
13:40:55.955 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 152ms
13:40:55.956 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 945: Transaction completed
13:40:55.957 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:945 DONE
13:40:55.959 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:40:55.960 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:40:55.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 18 98 81 12 86 76 4E 39 F8 79 5B 2B C3 1B 9D 25 F7 C9 88 11 FB C1 B6 F4 46
13:40:55.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
13:40:55.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
13:40:55.971 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:40:55.973 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Decapsulating COMMAND_CLASS_SECURITY
13:40:55.977 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: SECURITY_RXD 71 05 13 00
13:40:55.979 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
13:40:55.981 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_ALARM V1 NOTIFICATION_REPORT
13:40:55.983 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: ALARM report - 19 = 0
13:40:55.985 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: Alarm Type = null (19)
13:40:55.987 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveAlarmValueEvent
13:40:55.990 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveAlarmValueEvent
13:40:55.992 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ALARM, value = 0
13:40:55.996 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing ALARM
13:40:55.998 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a8c7d4bf:node3:alarm_general to OFF [OnOffType]
13:40:56.000 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing ALARM
13:40:56.002 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a8c7d4bf:node3:alarm_raw to {"type":"19","value":"0"} [StringType]
13:40:56.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
13:40:56.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@95dea8.
13:40:56.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:40:56.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:40:56.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:40:56.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
13:40:56.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
13:40:56.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
13:40:56.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
13:40:56.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:40:56.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
@chris part 2 of the previous reply
WHEN I DO FROM OPENHAB UI
13:46:53.621 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:57.759 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:a8c7d4bf:node3:lock_door --> ON
13:47:57.761 [DEBUG] [mmandclass.ZWaveDoorLockCommandClass] - NODE 3: Creating new message for application command DOORLOCK_SET, value 255
13:47:57.762 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
13:47:57.763 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Encapsulating message, endpoint 0
13:47:57.763 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY required on COMMAND_CLASS_DOOR_LOCK
13:47:57.764 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_DOOR_LOCK is required to be secured
13:47:57.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
13:47:57.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added to queue - size 0
13:47:57.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
13:47:57.767 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
13:47:57.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
13:47:57.768 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: listening == false, frequentlyListening == true, awake == false
13:47:57.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
13:47:57.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Transaction requires security
13:47:57.770 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: isNonceAvailable = null
13:47:57.771 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_GET version 1
13:47:57.771 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SECURITY
13:47:57.773 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request (0x00)
13:47:57.774 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xBB
13:47:57.775 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 98 40 25 A2 BB
13:47:57.777 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 98 40 25 A2 BB
13:47:57.778 [INFO ] [marthome.event.ItemStateChangedEvent] - Room_DoorLock_DoorLock_Switch changed from OFF to ON
13:47:57.779 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
13:47:57.780 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: Transaction Start type SendData
13:47:57.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 964: [WAIT_RESPONSE] requiresResponse=true callback: 162
13:47:57.783 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:47:57.792 [INFO ] [marthome.event.ItemStateChangedEvent] - Room_SerialControler_FramesAcknowledge_Label changed from 956 to 957
13:47:57.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SECURITY
13:47:57.791 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:47:57.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 128
13:47:57.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:47:57.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:47:57.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:47:57.802 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:47:57.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:47:57.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:47:59 NZDT 2017 - 2000ms
13:47:57.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
13:47:57.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:47:57.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:47:57.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 964: [WAIT_RESPONSE] requiresResponse=true callback: 162
13:47:57.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
13:47:57.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:57.810 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:47:57.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:47:59 NZDT 2017 - 1993ms
13:47:57.813 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:47:57.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:47:57.815 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xE8
13:47:57.816 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:57.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:47:59 NZDT 2017 - 1986ms
13:47:57.820 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'Room_DoorLock_DoorLock_Switch' received command ON
13:47:57.818 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:47:57.822 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:47:57.824 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:47:57.826 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:47:57.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:57.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:57.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:57.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 964: [WAIT_RESPONSE] requiresResponse=true callback: 162
13:47:57.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:47:57.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 964: [WAIT_RESPONSE] requiresResponse=true callback: 162
13:47:57.834 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:57.834 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:47:57.835 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:47:57.835 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:47:57.836 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance ST: WAIT_RESPONSE
13:47:57.836 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance WT: ApplicationCommandHandler {}
13:47:57.837 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:57.837 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance TO: WAIT_REQUEST
13:47:57.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 964: Advanced to WAIT_REQUEST
13:47:57.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 964: Transaction not completed
13:47:57.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:47:57.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
13:47:57.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:47:57.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:57.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:02 NZDT 2017 - 4994ms
13:47:59.092 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:47:59.096 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A2 00 00 83 CA
13:47:59.098 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 A2 00 00 83 CA
13:47:59.101 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xCA
13:47:59.102 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:47:59.104 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = A2 00 00 83
13:47:59.106 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:47:59.107 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:47:59.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=162, payload=A2 00 00 83
13:47:59.111 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=162, payload=A2 00 00 83
13:47:59.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=162, payload=A2 00 00 83
13:47:59.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 964: [WAIT_REQUEST] requiresResponse=true callback: 162
13:47:59.115 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:47:59.115 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:47:59.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 964: [WAIT_REQUEST] requiresResponse=true callback: 162
13:47:59.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 964: (Callback 162)
13:47:59.117 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
13:47:59.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 964: callback 162
13:47:59.119 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=162, payload=A2 00 00 83
13:47:59.120 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:47:59.120 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 03 0A 98 80 81 8C B3 4F 1A A4 7C 2E E7
13:47:59.121 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:47:59.121 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 162, Status = Transmission complete and ACK received(0)
13:47:59.122 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:47:59.123 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance ST: WAIT_REQUEST
13:47:59.123 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance WT: ApplicationCommandHandler {}
13:47:59.124 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 10 00 04 00 03 0A 98 80 81 8C B3 4F 1A A4 7C 2E E7
13:47:59.124 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xE7
13:47:59.127 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:47:59.125 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=162, payload=A2 00 00 83
13:47:59.128 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Message payload = 00 03 0A 98 80 81 8C B3 4F 1A A4 7C 2E
13:47:59.130 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler
13:47:59.130 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:47:59.131 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance TO: WAIT_DATA
13:47:59.132 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:47:59.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 964: Advanced to WAIT_DATA
13:47:59.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 0A 98 80 81 8C B3 4F 1A A4 7C 2E
13:47:59.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - XXXXXXXXXXXXXXXXX lastTransaction COMPLETED - at DATA - 162
13:47:59.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 0A 98 80 81 8C B3 4F 1A A4 7C 2E
13:47:59.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 964: Transaction not completed
13:47:59.142 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 0A 98 80 81 8C B3 4F 1A A4 7C 2E
13:47:59.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
13:47:59.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
13:47:59.144 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:47:59.145 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
13:47:59.146 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY check internal
13:47:59.147 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_REPORT
13:47:59.147 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: NONCE Received start...
13:47:59.148 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: NONCE Received start null
13:47:59.149 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: NONCE Received ZWaveNonce [nonceBytes=(81 8C B3 4F 1A A4 7C 2E ), timer=591191, valid=true]
13:47:59.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
13:47:59.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2e2660.
13:47:59.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking transaction 964 ApplicationCommandHandler.
13:47:59.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking transaction : state >> WAIT_DATA
13:47:59.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking transaction : node >> 3
13:47:59.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking transaction : class >> 152 == 152.
13:47:59.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking transaction : commd >> 128 == 128.
13:47:59.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2e2660.
13:47:59.156 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance ST: WAIT_DATA
13:47:59.157 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance WT: ApplicationCommandHandler {}
13:47:59.158 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance RX: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 0A 98 80 81 8C B3 4F 1A A4 7C 2E
13:47:59.159 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 964: TransactionAdvance TO: DONE
13:47:59.160 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:964 DONE
13:47:59.161 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:47:59.162 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:47:59.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
13:47:59.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:47:59.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:47:59.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
13:47:59.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue
13:47:59.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Transaction requires security
13:47:59.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: NONCE available so encap and send.
13:47:59.167 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_MESSAGE_ENCAPSULATION version 1
13:47:59.171 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: SECURITY_TXD 62 01 FF
13:47:59.172 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request (0x00)
13:47:59.173 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xBF
13:47:59.176 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1E 00 13 03 17 98 81 28 53 55 99 94 A2 86 68 F7 91 9F F2 81 B6 83 67 80 57 82 F3 D7 25 A3 BF
13:47:59.178 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 1E 00 13 03 17 98 81 28 53 55 99 94 A2 86 68 F7 91 9F F2 81 B6 83 67 80 57 82 F3 D7 25 A3 BF
13:47:59.179 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
13:47:59.180 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: Transaction Start type SendData
13:47:59.181 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 963: [WAIT_RESPONSE] requiresResponse=false callback: 163
13:47:59.181 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
13:47:59.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
13:47:59.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:47:59.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:59.184 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:47:59.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:01 NZDT 2017 - 1999ms
13:47:59.184 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:47:59.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 963: [WAIT_RESPONSE] requiresResponse=false callback: 163
13:47:59.185 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:59.185 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:47:59.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:01 NZDT 2017 - 1998ms
13:47:59.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:47:59.189 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:47:59.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:47:59.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 963: [WAIT_RESPONSE] requiresResponse=false callback: 163
13:47:59.191 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:47:59.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:47:59.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:47:59.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
13:47:59.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:47:59.194 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:59.195 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:47:59.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:01 NZDT 2017 - 1988ms
@chris rest of the previous reply [And Again sorry new members cannot upload files]
13:47:59.195 [INFO ] [marthome.event.ItemStateChangedEvent] - Room_SerialControler_FramesAcknowledge_Label changed from 957 to 958
13:47:59.197 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xE8
13:47:59.199 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:47:59.201 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:47:59.201 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:47:59.202 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:47:59.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:59.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:59.210 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:47:59.213 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A3 00 00 03 4B
13:47:59.215 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 A3 00 00 03 4B
13:47:59.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:59.216 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x4B
13:47:59.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 963: [WAIT_RESPONSE] requiresResponse=false callback: 163
13:47:59.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:47:59.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 963: [WAIT_RESPONSE] requiresResponse=false callback: 163
13:47:59.218 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:47:59.219 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:59.223 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:47:59.223 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = A3 00 00 03
13:47:59.224 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:47:59.225 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:47:59.226 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance ST: WAIT_RESPONSE
13:47:59.226 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:47:59.226 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance WT: null {}
13:47:59.227 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:47:59.228 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance TO: WAIT_REQUEST
13:47:59.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 963: Advanced to WAIT_REQUEST
13:47:59.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 963: Transaction not completed
13:47:59.230 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:47:59.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:47:59.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
13:47:59.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:47:59.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:47:59.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:04 NZDT 2017 - 4998ms
13:47:59.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=163, payload=A3 00 00 03
13:47:59.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=163, payload=A3 00 00 03
13:47:59.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=163, payload=A3 00 00 03
13:47:59.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 963: [WAIT_REQUEST] requiresResponse=false callback: 163
13:47:59.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:47:59.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 963: [WAIT_REQUEST] requiresResponse=false callback: 163
13:47:59.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 963: (Callback 163)
13:47:59.239 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
13:47:59.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 963: callback 163
13:47:59.240 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=163, payload=A3 00 00 03
13:47:59.241 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:47:59.242 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:47:59.242 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 163, Status = Transmission complete and ACK received(0)
13:47:59.243 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:47:59.243 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: Transaction COMPLETED
13:47:59.244 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance ST: DONE
13:47:59.244 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance WT: null {}
13:47:59.245 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=163, payload=A3 00 00 03
13:47:59.246 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 963: TransactionAdvance TO: DONE
13:47:59.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 66ms
13:47:59.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 963: Transaction completed
13:47:59.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:963 DONE
13:47:59.248 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:47:59.249 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:47:59.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:47:59.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
13:47:59.251 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
13:47:59.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
13:47:59.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
13:47:59.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:47:59.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:48:01.616 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:48:01.618 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 03 02 98 40 2A
13:48:01.619 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 04 00 03 02 98 40 2A
13:48:01.620 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x2A
13:48:01.621 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:48:01.622 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Message payload = 00 03 02 98 40
13:48:01.622 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:48:01.623 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:48:01.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 02 98 40
13:48:01.626 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 02 98 40
13:48:01.627 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 02 98 40
13:48:01.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
13:48:01.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
13:48:01.629 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:48:01.630 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SECURITY, endpoint 0
13:48:01.630 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY check internal
13:48:01.631 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SECURITY V1 SECURITY_NONCE_GET
13:48:01.631 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_REPORT version 1
13:48:01.632 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
13:48:01.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added to secure queue - size 1
13:48:01.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
13:48:01.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18d4d6.
13:48:01.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:48:01.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:48:01.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:48:01.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
13:48:01.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue
13:48:01.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
13:48:01.638 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request (0x00)
13:48:01.639 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x4C
13:48:01.640 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 03 0A 98 80 A9 87 21 EA 5B 92 C7 CA 25 A4 4C
13:48:01.641 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 11 00 13 03 0A 98 80 A9 87 21 EA 5B 92 C7 CA 25 A4 4C
13:48:01.642 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
13:48:01.643 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: Transaction Start type SendData
13:48:01.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 965: [WAIT_RESPONSE] requiresResponse=true callback: 164
13:48:01.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
13:48:01.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
13:48:01.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:48:01.646 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:48:01.646 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:48:01.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:48:01.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:48:01.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:03 NZDT 2017 - 1994ms
13:48:01.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 965: [WAIT_RESPONSE] requiresResponse=true callback: 164
13:48:01.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:48:01.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:03 NZDT 2017 - 1992ms
13:48:01.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
13:48:01.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 965: [WAIT_RESPONSE] requiresResponse=true callback: 164
13:48:01.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:48:01.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:48:01.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
13:48:01.657 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:48:01.657 [INFO ] [marthome.event.ItemStateChangedEvent] - Room_SerialControler_FramesAcknowledge_Label changed from 958 to 959
13:48:01.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:48:01.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:48:01.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:03 NZDT 2017 - 1987ms
13:48:01.659 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:48:01.662 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:48:01.665 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xE8
13:48:01.668 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:48:01.670 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:48:01.674 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:48:01.677 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:48:01.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:48:01.684 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:48:01.687 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:48:01.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:48:01.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 965: [WAIT_RESPONSE] requiresResponse=true callback: 164
13:48:01.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:48:01.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 965: [WAIT_RESPONSE] requiresResponse=true callback: 164
13:48:01.689 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:48:01.690 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:48:01.690 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A4 00 00 03 4C
13:48:01.691 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:48:01.691 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:48:01.692 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance ST: WAIT_RESPONSE
13:48:01.692 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance WT: null {}
13:48:01.693 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
13:48:01.694 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance TO: WAIT_REQUEST
13:48:01.694 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 A4 00 00 03 4C
13:48:01.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 965: Advanced to WAIT_REQUEST
13:48:01.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 965: Transaction not completed
13:48:01.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:48:01.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
13:48:01.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:48:01.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:48:01.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Nov 18 13:48:06 NZDT 2017 - 4997ms
13:48:01.700 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x4C
13:48:01.701 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:48:01.703 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = A4 00 00 03
13:48:01.705 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:48:01.707 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:48:01.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=164, payload=A4 00 00 03
13:48:01.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=164, payload=A4 00 00 03
13:48:01.714 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=164, payload=A4 00 00 03
13:48:01.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 965: [WAIT_REQUEST] requiresResponse=true callback: 164
13:48:01.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:48:01.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 965: [WAIT_REQUEST] requiresResponse=true callback: 164
13:48:01.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 965: (Callback 164)
13:48:01.717 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
13:48:01.718 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 965: callback 164
13:48:01.719 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:48:01.719 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=164, payload=A4 00 00 03
13:48:01.721 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:48:01.723 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:48:01.723 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 04 00 03 18 98 81 ED EF 76 7E AF 94 4E 6E 6C 71 FA EF 51 A9 37 EB DB ED 04 68 C9 8B C2
13:48:01.725 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 164, Status = Transmission complete and ACK received(0)
13:48:01.725 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 1E 00 04 00 03 18 98 81 ED EF 76 7E AF 94 4E 6E 6C 71 FA EF 51 A9 37 EB DB ED 04 68 C9 8B C2
13:48:01.726 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xC2
13:48:01.726 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:48:01.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:48:01.728 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Message payload = 00 03 18 98 81 ED EF 76 7E AF 94 4E 6E 6C 71 FA EF 51 A9 37 EB DB ED 04 68 C9 8B
13:48:01.728 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: Transaction COMPLETED
13:48:01.729 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:48:01.730 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:48:01.730 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance ST: DONE
13:48:01.732 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance WT: null {}
13:48:01.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 18 98 81 ED EF 76 7E AF 94 4E 6E 6C 71 FA EF 51 A9 37 EB DB ED 04 68 C9 8B
13:48:01.735 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=164, payload=A4 00 00 03
13:48:01.736 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 965: TransactionAdvance TO: DONE
13:48:01.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 18 98 81 ED EF 76 7E AF 94 4E 6E 6C 71 FA EF 51 A9 37 EB DB ED 04 68 C9 8B
13:48:01.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 96ms
13:48:01.741 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 965: Transaction completed
13:48:01.742 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:965 DONE
13:48:01.744 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:48:01.746 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:48:01.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=3, callback=0, payload=00 03 18 98 81 ED EF 76 7E AF 94 4E 6E 6C 71 FA EF 51 A9 37 EB DB ED 04 68 C9 8B
13:48:01.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
13:48:01.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
13:48:01.755 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:48:01.757 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Decapsulating COMMAND_CLASS_SECURITY
13:48:01.763 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: SECURITY_RXD 71 05 18 01
13:48:01.766 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
13:48:01.767 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_ALARM V1 NOTIFICATION_REPORT
13:48:01.768 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: ALARM report - 24 = 1
13:48:01.770 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 3: Alarm Type = null (24)
13:48:01.771 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveAlarmValueEvent
13:48:01.773 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveAlarmValueEvent
13:48:01.774 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ALARM, value = 1
13:48:01.778 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing ALARM
13:48:01.779 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a8c7d4bf:node3:alarm_general to ON [OnOffType]
13:48:01.781 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing ALARM
13:48:01.783 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a8c7d4bf:node3:alarm_raw to {"type":"24","value":"1"} [StringType]
13:48:01.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
13:48:01.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1f5912a.
13:48:01.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:48:01.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:48:01.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:48:01.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
13:48:01.794 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
13:48:01.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
13:48:01.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
13:48:01.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:48:01.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
I’m wondering what your problem is… Above you stated -:
Should this state “do not get updated in the UI”?
Looking at the log -:
I see the following -:
This looks fine - the notifications are being sent, but because the lock doesnt update the lock state, the binding doesn’t either. You need to use a rule to link the channels together.
I know this is a pain - the lock should really send a lock state update, but they don’t. I think in future we’ll be able to better handle this, but for now, you need a rule…
1 Like
Just patiently checking buy has Santa sent the new toy, have u had chance to fight it?
Yes - it arrived on Saturday but I didn’t yet find time to look at this due to other issues. I will look tonight or tomorrow.
OH 2.2.0 snapshot 1083
Zwave 2.2.0.201711152139
I reincluded a BE469 (not through OH), it has completed initialization (been a couple days now with a couple reboots), I can control it through the UI, but I am not getting alarm reports. I assume this is due to not having associations. Habmin shows the Associations as blank, and when saving an association to the controller, I get the error we’ve previously discussed, but I didn’t realize this may actually be preventing the association from going through. I see this in the log, but that’s it. Shouldn’t there be a CONFIGURATION_SET?
2017-11-21 13:39:08.117 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 95: Configuration update received
2017-11-21 13:39:08.132 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 95: Configuration update group_1 to [node_1_0]Please try this test version. I can’t seem to get my device to report anything at the moment and prefer not to spend too much time trying to get it working as I only bought it for testing! I can see the associations being set as I expect, so hopefully it’s working.
1 Like
So third time is a charm. Trying to get my danalock included once again. First time in the start of the year worked first try, then last time took about 1000000 tries. This time I think I’ve tried about 200000000 times. Lock 10 cm from UZB-stick. Can someone who knows the logging well have a look?
As far as I can understand it takes more than 20 sec, which is too long? Why could this be, possibly battery level?
Edit: Somehow randomly got it to work, don’t know why don’t know how.