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

vespaman · April 29, 2017, 12:42pm

Thanks, that was much easier!
Just to double check, before I re-add: I now see 2.1.0.201704261428 active. Is this the current refactored binding?

…Edit: no, I have also 2.1.0.201704232237 as installed.

chris · April 29, 2017, 12:49pm

This looks to be the last version I generated here, so it should be the one to use.

vespaman · April 29, 2017, 12:59pm

OK.
So I have uninstalled zwave binding from paper UI, I have also removed my ‘zwave’ in addons.cfg.
Now when I start, I have 2.1.0.201704232237 as installed. So far so good.

But:-
If I try to start it, by using bundle:start, I get

openhab> bundle:start 219
Error executing command: Error executing command on bundles:
        Error starting bundle 219: Could not resolve module: org.openhab.binding.zwave [219]
  Unresolved requirement: Import-Package: gnu.io

I’m sure I’m doing something wrong - it was quite some time since I added bindings manually…

chris · April 29, 2017, 1:01pm

Yes - take a look at the top of this thread - about 6 to 8 messages in there’s an explanation of this - you need to install the serial library.

vespaman · April 29, 2017, 3:00pm

OK, so I got further:- I have binding up, but I had issues adding back the items, so I stopped, and added back the jsondb things (basically copied back the json db file as it was), and deleted the things manually.

Now things can be added, but all but a few arrived as unknowns. So I removed everything again, incl serial controller. Stopped OH, removed all xml files. Restarted.
Still, after pressing the thing scan->zwave, all zwave nodes arrives as unknown.
Slowly, very slowly, I’m getting the xml data back. I have three xml files after 15-30 minutes.

The thread is very long, and it is hard to search if this behaviour is expected/common.

vespaman · April 29, 2017, 3:11pm

It seams that there’s timeouts here and there in the log. Could it be that the nodes cannot be found without a heal?
Snippet:

17:09:02.019 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
17:09:02.019 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 70: TID 211: Timeout at state WAIT_DATA. 3 retries remaining.
17:09:02.020 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 211: Transaction is current transaction, so clearing!!!!!
17:09:02.020 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 211: Transaction CANCELLED
17:09:02.020 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 70: notifyTransactionResponse TID:211 CANCELLED
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
17:09:02.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: listening == false, frequentlyListening == false, awake == false
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 211: Transaction event listener: DONE: CANCELLED -> 
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Node not awake!
17:09:02.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: listening == false, frequentlyListening == false, awake == false
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 70: -- To notify -- TIMEOUT_WAITING_FOR_DATA
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Node not awake!
17:09:02.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: listening == false, frequentlyListening == false, awake == false
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Node not awake!
17:09:02.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
17:09:02.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: listening == true, frequentlyListening == false, awake == false
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
17:09:02.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
17:09:02.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 211 -- 
17:09:02.021 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 16 8D 
17:09:02.021 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 70: Node Init response (5) TIMEOUT_WAITING_FOR_DATA
17:09:02.021 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 16 8D 
17:09:02.021 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 70: No data from device, but it was ACK'd. Possibly not supported? (Try 5)
17:09:02.022 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
17:09:02.022 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 213: Transaction Start type RequestNodeInfo 
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 213: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:09:04 CEST 2017 - 2000ms
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 213: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:09:02.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:09:04 CEST 2017 - 2000ms
17:09:02.023 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 213: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:09:02.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:09:04 CEST 2017 - 1999ms
17:09:02.029 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 
17:09:02.029 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:09:02.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:09:02.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 213: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 213: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:09:02.030 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:09:02.030 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
17:09:02.030 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 213: TransactionAdvance ST: WAIT_RESPONSE
17:09:02.030 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 213: TransactionAdvance WT: ApplicationUpdate {}
17:09:02.030 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 213: TransactionAdvance RX: Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:09:02.030 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 213: TransactionAdvance TO: WAIT_DATA
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 213: Advanced to WAIT_DATA
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: TID 213: Transaction not completed
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:09:02.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:09:27 CEST 2017 - 25000ms

chris · April 29, 2017, 3:19pm

When providing a log, the bit of interest is always before the event - not after… Eg the useful information about your timeout is logged before the timeout message…

vespaman · April 29, 2017, 3:32pm

Sorry for that. Here’s a longer snippet. Not sure if it is long enough though. I’m guessing the last timeout is for node 78.
The forum only allows 32k, so I had to reduce rather much…

Node 78 is a door contact, battery device, so I guess it might be OK for taking its time.
The xmls are filling up, about 8-10 of them after an hour. But nodes are still “unknown”.

17:21:40.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : state >> WAIT_DATA
17:21:40.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : node  >> 11
17:21:40.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : class >> 132 == null.
17:21:40.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : commd >> 7 == null.
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@63077427.
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:40.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:21:51 CEST 2017 - 10817ms
17:21:40.939 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 10 4E 02 84 07 2C 
17:21:40.940 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=78, callback=16, payload=10 4E 02 84 07 
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=78, callback=16, payload=10 4E 02 84 07 
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=78, callback=16, payload=10 4E 02 84 07 
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 265: [WAIT_DATA] requiresResponse=true callback: 0
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Application Command Request (ALIVE:FAILED_CHECK)
17:21:40.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: Incoming command class COMMAND_CLASS_WAKE_UP, endpoint 0
17:21:40.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: SECURITY not supported
17:21:40.940 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 78: Received COMMAND_CLASS_WAKE_UP V0 WAKE_UP_NOTIFICATION
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Commands processed 1.
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@296588b.
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction 265  ApplicationUpdate.
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : state >> WAIT_DATA
17:21:40.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : node  >> 11
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : class >> 132 == null.
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Checking transaction : commd >> 7 == null.
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Command NOT verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@296588b.
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:40.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:21:51 CEST 2017 - 10636ms
17:21:42.295 [INFO ] [marthome.event.ItemStateChangedEvent] - HouseVolts changed from 228.0 to 228.2
17:21:42.300 [INFO ] [marthome.event.ItemStateChangedEvent] - HousePhase1W changed from 577.0 to 568.154
17:21:42.301 [INFO ] [marthome.event.ItemStateChangedEvent] - HousePhase2W changed from 186.692 to 186.154
17:21:42.302 [INFO ] [marthome.event.ItemStateChangedEvent] - HousePhase3W changed from 203.769 to 212.769
17:21:42.303 [INFO ] [marthome.event.ItemStateChangedEvent] - Energy_ch11 changed from 385.231 to 381.538
17:21:42.303 [INFO ] [marthome.event.ItemStateChangedEvent] - Energy_ch12 changed from 37.308 to 60.923
17:21:42.304 [INFO ] [marthome.event.ItemStateChangedEvent] - Energy_ch17 changed from 134.615 to 136.231
17:21:42.304 [INFO ] [marthome.event.ItemStateChangedEvent] - Energy_ch18 changed from 34.692 to 34.462
17:21:42.304 [INFO ] [marthome.event.ItemStateChangedEvent] - Energy_ch20 changed from 26.077 to 26.462
17:21:42.305 [INFO ] [marthome.event.ItemStateChangedEvent] - Energy_ch24 changed from 107.692 to 107.615
17:21:42.306 [INFO ] [marthome.event.ItemStateChangedEvent] - Energy_ch31 changed from 39.846 to 39.769
17:21:42.310 [INFO ] [marthome.event.ItemStateChangedEvent] - HouseTotalW changed from 967.461 to 967.077
17:21:43.391 [WARN ] [ector.internal.EpsonProjectorBinding] - Couldn't execute command 'Zoom', org.openhab.binding.epsonprojector.internal.EpsonProjectorException: Error response received
17:21:43.391 [ERROR] [ector.internal.EpsonProjectorBinding] - No response received from command 'Zoom'
17:21:50.011 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: listening == false, frequentlyListening == false, awake == true
17:21:50.012 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: WakeupTimerTask 0 Messages waiting, state FAILED_CHECK
17:21:50.012 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: WakeupTimerTask First iteration
17:21:51.577 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
17:21:51.577 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 11: TID 265: Timeout at state WAIT_DATA. 3 retries remaining.
17:21:51.577 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 265: Transaction is current transaction, so clearing!!!!!
17:21:51.577 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 265: Transaction CANCELLED
17:21:51.577 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
17:21:51.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: notifyTransactionResponse TID:265 CANCELLED
17:21:51.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
17:21:51.577 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: listening == false, frequentlyListening == false, awake == false
17:21:51.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 265: Transaction event listener: DONE: CANCELLED -> 
17:21:51.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Node not awake!
17:21:51.577 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: listening == false, frequentlyListening == false, awake == false
17:21:51.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: -- To notify -- TIMEOUT_WAITING_FOR_DATA
17:21:51.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Node not awake!
17:21:51.578 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
17:21:51.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 265 -- 
17:21:51.579 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: listening == false, frequentlyListening == false, awake == false
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Node not awake!
17:21:51.579 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Node Init response (0) TIMEOUT_WAITING_FOR_DATA
17:21:51.579 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: listening == true, frequentlyListening == false, awake == false
17:21:51.579 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: No data from device, but it was ACK'd. Possibly not supported? (Try 0)
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
17:21:51.579 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 03 98 
17:21:51.579 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 03 98 
17:21:51.579 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
17:21:51.579 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 267: Transaction Start type RequestNodeInfo 
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 267: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
17:21:51.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
17:21:51.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:51.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:21:53 CEST 2017 - 2000ms
17:21:51.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 267: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:21:51.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:51.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:21:53 CEST 2017 - 2000ms
17:21:51.580 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:21:51.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:21:51.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 267: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:51.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:21:53 CEST 2017 - 1999ms
17:21:51.590 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 
17:21:51.590 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:21:51.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:21:51.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:21:51.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:21:51.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 267: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:21:51.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:21:51.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 267: [WAIT_RESPONSE] requiresResponse=true callback: 0
17:21:51.590 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:21:51.590 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
17:21:51.591 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 267: TransactionAdvance ST: WAIT_RESPONSE
17:21:51.591 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 267: TransactionAdvance WT: ApplicationUpdate {}
17:21:51.591 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 267: TransactionAdvance RX: Message: class=RequestNodeInfo[0x60], type=Response[0x01], dest=255, callback=0, payload=01 
17:21:51.591 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 267: TransactionAdvance TO: WAIT_DATA
17:21:51.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 267: Advanced to WAIT_DATA
17:21:51.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 267: Transaction not completed
17:21:51.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:21:51.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:51.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:51.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:51.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:16 CEST 2017 - 25000ms
17:21:52.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@12c963
17:21:52.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Adding to device queue
17:21:52.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Added to queue - size 44
17:21:52.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:52.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:52.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:52.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:16 CEST 2017 - 24202ms
17:21:56.499 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 31: Requesting IsFailedNode status from controller.
17:21:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@7f1c3189
17:21:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
17:21:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 45
17:21:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:16 CEST 2017 - 20092ms
17:21:56.502 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 78: Requesting IsFailedNode status from controller.
17:21:56.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@353e156c
17:21:56.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
17:21:56.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 46
17:21:56.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:56.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:56.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:56.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:16 CEST 2017 - 20088ms
17:21:58.990 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 06 00 49 81 00 00 31 
17:21:58.990 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:21:58.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationUpdate[0x49], type=Request[0x00], dest=0, callback=129, payload=81 00 00 
17:21:58.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationUpdate[0x49], type=Request[0x00], dest=0, callback=129, payload=81 00 00 
17:21:58.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationUpdate[0x49], type=Request[0x00], dest=0, callback=129, payload=81 00 00 
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 267: [WAIT_DATA] requiresResponse=true callback: 0
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 267: [WAIT_DATA] requiresResponse=true callback: 0
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 267: (Callback 0)
17:21:58.991 [DEBUG] [essage.ApplicationUpdateMessageClass] - XXXXXXXX Correlating ApplicationUpdateMessageClass ApplicationUpdate ApplicationUpdate
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
17:21:58.991 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[0x49], type=Request[0x00], dest=0, callback=129, payload=81 00 00 
17:21:58.991 [DEBUG] [essage.ApplicationUpdateMessageClass] - Application update request. Node Info Request Failed (Unknown Node).
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:21:58.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:16 CEST 2017 - 17600ms
17:22:00.011 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: listening == false, frequentlyListening == false, awake == true
17:22:00.011 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: WakeupTimerTask 0 Messages waiting, state FAILED_CHECK
17:22:00.011 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: No more messages, go back to sleep
17:22:00.011 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 78: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
17:22:00.011 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
17:22:00.011 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: Encapsulating message, endpoint 0
17:22:00.011 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: SECURITY not supported
17:22:00.011 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
17:22:00.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@438655ac
17:22:00.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Adding to device queue
17:22:00.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: Added to queue - size 46
17:22:00.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:22:00.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:22:00.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:22:00.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:16 CEST 2017 - 16579ms
17:22:16.591 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
17:22:16.591 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 3: TID 267: Timeout at state WAIT_DATA. 3 retries remaining.
17:22:16.591 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 267: Transaction is current transaction, so clearing!!!!!
17:22:16.591 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 267: Transaction CANCELLED
17:22:16.591 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
17:22:16.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:267 CANCELLED
17:22:16.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
17:22:16.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 267: Transaction event listener: DONE: CANCELLED -> 
17:22:16.592 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 78: listening == false, frequentlyListening == false, awake == true
17:22:16.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
17:22:16.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: -- To notify -- TIMEOUT_WAITING_FOR_DATA
17:22:16.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
17:22:16.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 267 -- 
17:22:16.593 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 4E 02 84 08 25 23 23 
17:22:16.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) TIMEOUT_WAITING_FOR_DATA
17:22:16.593 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 78: Sending REQUEST Message = 01 09 00 13 4E 02 84 08 25 23 23 
17:22:16.593 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: No data from device, but it was ACK'd. Possibly not supported? (Try 0)
17:22:16.594 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
17:22:16.594 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: Transaction Start type SendData 
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 272: [WAIT_RESPONSE] requiresResponse=true callback: 35
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:18 CEST 2017 - 2000ms
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 272: [WAIT_RESPONSE] requiresResponse=true callback: 35
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:22:16.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:18 CEST 2017 - 2000ms
17:22:16.594 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 272: [WAIT_RESPONSE] requiresResponse=true callback: 35
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:22:16.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:18 CEST 2017 - 1999ms
17:22:16.601 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
17:22:16.601 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:22:16.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
17:22:16.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
17:22:16.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
17:22:16.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 272: [WAIT_RESPONSE] requiresResponse=true callback: 35
17:22:16.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
17:22:16.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 272: [WAIT_RESPONSE] requiresResponse=true callback: 35
17:22:16.602 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
17:22:16.602 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 78: Sent Data successfully placed on stack.
17:22:16.602 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: TransactionAdvance ST: WAIT_RESPONSE
17:22:16.602 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: TransactionAdvance WT: null {}
17:22:16.602 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
17:22:16.602 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: TransactionAdvance TO: WAIT_REQUEST
17:22:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 272: Advanced to WAIT_REQUEST
17:22:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 78: TID 272: Transaction not completed
17:22:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
17:22:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:22:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:22:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:22:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:21 CEST 2017 - 5000ms
17:22:18.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@24ab2c4f
17:22:18.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
17:22:18.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added to queue - size 46
17:22:18.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:22:18.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:22:18.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:22:18.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sat Apr 29 17:22:21 CEST 2017 - 2796ms
17:22:21.602 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
17:22:21.603 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 78: TID 272: Timeout at state WAIT_REQUEST. 3 retries remaining.
17:22:21.603 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
17:22:21.603 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: Transaction ABORTED
17:22:21.603 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA

Martin_Larsson · May 3, 2017, 9:19am

@chris will you be releasing this binding officially soon? It works OK for me now. Are you still working on things?

Reason why I am asking is that I would like to have it installed via HABmin instead of putting a file in the addons dir. I guess updating add-ons is easier when installed via HABmin but I havnt looked in to updating add-ons yet!?

chris · May 3, 2017, 9:26am

No - that’s not the plan…

The plan is to merge this into the master after 2.1 is released (which I think is planned for June). This version is a major change, and I don’t want to merge it prior to a stable release.

Of course ;). There are things that I’d like to resolve before merging this, but there are ‘always’ things to work on.

vespaman · May 3, 2017, 6:15pm

@chris do you have any suggestion on how to proceed with my issue? I assume the log above is too short…
In short, no device arrives beyond 0x7fffffff on manufacturer/device in their xml files, apart from node 1, the stick, which seams more complete. I have restarted plenty times, and waited about 24h before giving up.
My house has between 60-70 zwave devices, about 10 of which are battery.

Going back between the refactored binding and the vanilla is not a problem, the vanilla starts up without any issues. I have them in different base OH subdirectories.

chris · May 3, 2017, 7:34pm

This statement worries me - it should not be possible to do this. You would need to delete all things and re-add them if you change between the master and development versions. I would suspect if you are able to swap between them easily, then something is wrong.

vespaman · May 3, 2017, 7:36pm

Even if they are in complete different OH main directories?

chris · May 3, 2017, 7:37pm

Ok, no, if they are completely different installations then that’s ok. I thought from your statement that you were just swapping the binding.

In that case, I’ve no idea why none of your devices would work .

vespaman · May 3, 2017, 7:41pm

The only thing that also might be a clue, is that the XMLs are added very slowly, not at all in the pace of the vanilla binding.
And upon restart, the binding says that the existing XMLs are not in good shape, therefore ignoring them. I guess this is because they are still incomplete, and thus natural/intended behaviour.

chris · May 3, 2017, 7:44pm

No - this is no clue at all unfortunately.

This shouldn’t happen if they have been rewritten by the new binding - can you post one here?

vespaman · May 3, 2017, 7:46pm

Of course! This example is an old Fibaro dimmer;

<node>
  <homeId>0xc2f5c852</homeId>
  <nodeId>15</nodeId>
  <version>4</version>
  <manufacturer>0x7fffffff</manufacturer>
  <deviceId>0x7fffffff</deviceId>
  <deviceType>0x7fffffff</deviceType>
  <listening>true</listening>
  <frequentlyListening>false</frequentlyListening>
  <routing>true</routing>
  <security>false</security>
  <beaming>true</beaming>
  <maxBaudRate>40000</maxBaudRate>
  <sleepDelay>1000</sleepDelay>
  <associationGroups/>
  <endpoints>
    <entry>
      <int>0</int>
      <endPoint>
        <deviceClass>
          <basicDeviceClass>BASIC_TYPE_ROUTING_SLAVE</basicDeviceClass>
          <genericDeviceClass>GENERIC_TYPE_SWITCH_MULTILEVEL</genericDeviceClass>
          <specificDeviceClass>SPECIFIC_TYPE_POWER_SWITCH_MULTILEVEL</specificDeviceClass>
        </deviceClass>
        <endpointId>0</endpointId>
        <secureCommandClasses/>
        <supportedCommandClasses>
          <entry>
            <commandClass>COMMAND_CLASS_NO_OPERATION</commandClass>
            <COMMAND__CLASS__NO__OPERATION>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
            </COMMAND__CLASS__NO__OPERATION>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_BASIC</commandClass>
            <COMMAND__CLASS__BASIC>
              <version>0</version>
              <instances>1</instances>
              <versionSupported>0</versionSupported>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__BASIC>
          </entry>
        </supportedCommandClasses>
      </endPoint>
    </entry>
  </endpoints>
  <nodeNeighbors>
    <int>1</int>
    <int>3</int>
    <int>4</int>
    <int>6</int>
    <int>8</int>
    <int>9</int>
    <int>11</int>
    <int>12</int>
    <int>14</int>
    <int>16</int>
    <int>17</int>
    <int>18</int>
    <int>19</int>
    <int>20</int>
    <int>21</int>
    <int>22</int>
    <int>23</int>
    <int>26</int>
    <int>27</int>
    <int>28</int>
    <int>29</int>
    <int>30</int>
    <int>31</int>
    <int>32</int>
    <int>34</int>
    <int>36</int>
    <int>38</int>
    <int>40</int>
    <int>41</int>
    <int>42</int>
    <int>43</int>
    <int>46</int>
    <int>54</int>
    <int>56</int>
    <int>57</int>
    <int>61</int>
    <int>62</int>
    <int>68</int>
    <int>69</int>
    <int>72</int>
    <int>73</int>
    <int>78</int>
    <int>84</int>
  </nodeNeighbors>
</node>

chris · May 3, 2017, 7:47pm

Thanks - it won’t like the manufacturer and will not use the file. I’m not sure what’s happening really without seeing a log.

vespaman · May 3, 2017, 7:54pm

A longer/earlier than the fragment above?
I will gladly send you any kind of log - since I don’t think there’s a chance I can get too much further on my own.
Shall I email you a complete log from start, how many hours would you want?

Unfortunately, the existing logs I have does not any longer contain the start, so I’ll have to clear them and start all over, so if you want hours, it will not arrive until tomorrow. But then again, I guess you have other things to do as well, so this might not be a problem…

chris · May 3, 2017, 7:57pm

Yes - both probably. Certainly longer.

Yes - a complete log from start would be good. Let’s go for a 10MB file - however long that is and we’ll see what that shows for starters.

Can you raise a ticket on my website - it just makes it easier to track - you can upload files to the ticket up to 20MB I think.

I’m trying to avoid people email me logs as it gets hard to work out what log goes with what request - it’s fine for a single log, but if it goes on for a few days, and more people email different log, it’s hard to keep track - hence the tickets ;).