Aeotec Dimmer takes hours to initialise?

Add-ons Bindings
1

Hi All

a 10 node network and this takes hours. I just included a new Aeotec Dimmer Nano and its showing unknown device, cant do a heal cause the initialisation isn’t complete. I find this rather odd.

Any thought as to why this is occurring? No XML is created as yet.

EDIT: after I restarted the binding, it picked up that it was a ZW111. Why does a restart make this work?


05-Jul-2019 11:05:57.935 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 17: Configuration update received
05-Jul-2019 11:05:57.936 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 17: Configuration update set action_heal to true (Boolean)
05-Jul-2019 11:05:57.936 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 17: Starting heal on node!
05-Jul-2019 11:05:57.936 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 17: Can not start heal as initialisation is not complete (GET_CONFIGURATION).
05-Jul-2019 11:06:15.230 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 17: ZWaveCommandClassTransactionPayload - send to node
05-Jul-2019 11:06:15.230 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 17: Encapsulating message, endpoint 0
05-Jul-2019 11:06:15.230 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 17: SECURITY not supported
05-Jul-2019 11:06:15.230 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 17: Command Class COMMAND_CLASS_CONFIGURATION is NOT required to be secured
05-Jul-2019 11:06:15.231 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@2f69c52
05-Jul-2019 11:06:15.231 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: Adding to device queue
05-Jul-2019 11:06:15.232 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: Added 211 to queue - size 2
05-Jul-2019 11:06:15.232 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
05-Jul-2019 11:06:15.232 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: listening == false, frequentlyListening == false, awake == false
05-Jul-2019 11:06:15.232 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Node not awake!
05-Jul-2019 11:06:15.232 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 17: listening == true, frequentlyListening == false, awake == false
05-Jul-2019 11:06:15.232 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
05-Jul-2019 11:06:15.232 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
05-Jul-2019 11:06:15.232 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 17: Creating empty message of class = SendData (0x13), type = Request
05-Jul-2019 11:06:15.232 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 107
05-Jul-2019 11:06:15.232 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 11 03 70 05 7A 25 B5 6B
05-Jul-2019 11:06:15.232 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 17: Sending REQUEST Message = 01 0A 00 13 11 03 70 05 7A 25 B5 6B
05-Jul-2019 11:06:15.233 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
05-Jul-2019 11:06:15.233 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: Transaction Start type SendData
05-Jul-2019 11:06:15.233 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 211: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 181
05-Jul-2019 11:06:15.233 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_CONFIGURATION
05-Jul-2019 11:06:15.233 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 6
05-Jul-2019 11:06:15.233 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
05-Jul-2019 11:06:15.233 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Jul 05 11:06:17 AEST 2019 - 2000ms
05-Jul-2019 11:06:15.233 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 211: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 181
05-Jul-2019 11:06:15.233 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
05-Jul-2019 11:06:15.233 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Jul 05 11:06:17 AEST 2019 - 2000ms
05-Jul-2019 11:06:15.234 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
05-Jul-2019 11:06:15.234 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
05-Jul-2019 11:06:15.234 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
05-Jul-2019 11:06:15.234 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
05-Jul-2019 11:06:15.234 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 211: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 181
05-Jul-2019 11:06:15.234 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
05-Jul-2019 11:06:15.235 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
05-Jul-2019 11:06:15.235 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
05-Jul-2019 11:06:15.235 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
05-Jul-2019 11:06:15.235 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
05-Jul-2019 11:06:15.235 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Jul 05 11:06:17 AEST 2019 - 1998ms
05-Jul-2019 11:06:15.240 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
05-Jul-2019 11:06:15.240 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
05-Jul-2019 11:06:15.240 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
05-Jul-2019 11:06:15.241 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = -24
05-Jul-2019 11:06:15.241 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
05-Jul-2019 11:06:15.241 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
05-Jul-2019 11:06:15.241 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
05-Jul-2019 11:06:15.241 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
05-Jul-2019 11:06:15.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
05-Jul-2019 11:06:15.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
05-Jul-2019 11:06:15.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 211: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 181
05-Jul-2019 11:06:15.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
05-Jul-2019 11:06:15.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 211: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 181
05-Jul-2019 11:06:15.242 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
05-Jul-2019 11:06:15.242 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
05-Jul-2019 11:06:15.242 [TRACE] [ternal.protocol.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
05-Jul-2019 11:06:15.242 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 17: sentData successfully placed on stack.
05-Jul-2019 11:06:15.242 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance ST: WAIT_RESPONSE
05-Jul-2019 11:06:15.242 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance WT: ApplicationCommandHandler {}
05-Jul-2019 11:06:15.242 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
05-Jul-2019 11:06:15.242 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance TO: WAIT_REQUEST
05-Jul-2019 11:06:15.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 211: Advanced to WAIT_REQUEST
05-Jul-2019 11:06:15.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: TID 211: Transaction not completed
05-Jul-2019 11:06:15.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
05-Jul-2019 11:06:15.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
05-Jul-2019 11:06:15.242 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
05-Jul-2019 11:06:15.242 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
05-Jul-2019 11:06:15.242 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Jul 05 11:06:20 AEST 2019 - 5000ms
05-Jul-2019 11:06:15.280 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
05-Jul-2019 11:06:15.281 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 B5 00 00 05 5B
05-Jul-2019 11:06:15.281 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 B5 00 00 05 5B
05-Jul-2019 11:06:15.281 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 91
05-Jul-2019 11:06:15.281 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
05-Jul-2019 11:06:15.281 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 0: Message payload = B5 00 00 05
05-Jul-2019 11:06:15.281 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
05-Jul-2019 11:06:15.281 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
05-Jul-2019 11:06:15.282 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=181, payload=B5 00 00 05
05-Jul-2019 11:06:15.282 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=181, payload=B5 00 00 05
05-Jul-2019 11:06:15.282 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 211: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 181
05-Jul-2019 11:06:15.282 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
05-Jul-2019 11:06:15.282 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 211: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 181
05-Jul-2019 11:06:15.282 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 211: (Callback 181)
05-Jul-2019 11:06:15.282 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
05-Jul-2019 11:06:15.282 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 211: callback 181
05-Jul-2019 11:06:15.282 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=181, payload=B5 00 00 05
05-Jul-2019 11:06:15.282 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
05-Jul-2019 11:06:15.282 [TRACE] [ternal.protocol.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
05-Jul-2019 11:06:15.282 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 17: SendData Request. CallBack ID = 181, Status = Transmission complete and ACK received(0)
05-Jul-2019 11:06:15.282 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance ST: WAIT_REQUEST
05-Jul-2019 11:06:15.282 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance WT: ApplicationCommandHandler {}
05-Jul-2019 11:06:15.283 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=181, payload=B5 00 00 05
05-Jul-2019 11:06:15.283 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler
05-Jul-2019 11:06:15.283 [TRACE] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: TransactionAdvance TO: WAIT_DATA
05-Jul-2019 11:06:15.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 211: Advanced to WAIT_DATA
05-Jul-2019 11:06:15.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: TID 211: Transaction not completed
05-Jul-2019 11:06:15.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
05-Jul-2019 11:06:15.283 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
05-Jul-2019 11:06:15.283 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
05-Jul-2019 11:06:15.283 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
05-Jul-2019 11:06:15.283 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Jul 05 11:06:20 AEST 2019 - 5000ms
05-Jul-2019 11:06:20.284 [TRACE] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions
05-Jul-2019 11:06:20.284 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 17: TID 211: Timeout at state WAIT_DATA. 3 retries remaining.
05-Jul-2019 11:06:20.284 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 211: Transaction CANCELLED
05-Jul-2019 11:06:20.284 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
05-Jul-2019 11:06:20.284 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 17: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
05-Jul-2019 11:06:20.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 17: notifyTransactionResponse TID:211 CANCELLED
05-Jul-2019 11:06:20.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
05-Jul-2019 11:06:20.285 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 15: listening == false, frequentlyListening == false, awake == false
05-Jul-2019 11:06:20.285 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 15: Node not awake!
05-Jul-2019 11:06:20.285 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
05-Jul-2019 11:06:20.285 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - STOP transaction timer
05-Jul-2019 11:06:20.285 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 211: Transaction event listener: DONE: CANCELLED ->
05-Jul-2019 11:06:20.286 [TRACE] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 211 --
05-Jul-2019 11:06:20.286 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 17: Node Init response (8) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@452f47b5
05-Jul-2019 11:06:20.286 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 17: No data from device, but it was ACK'd. Possibly not supported? (Try 8)
2

Could it be a signal quality problem? Might be worth trying it with the controller and device in close proximity, at least to rule that out. 10 devices is not that many if you’re trying to cover a large area.

3

Hi leif, the 10 devices are over a small area, we are talking less than 5 meters between each device. This particular device is around the corner from the controller, but direct line of sight between the controller and the device is about 6" of solid concrete. That said, its right next to a device which is direct LOS from the controller.

Surely it cant be signal, zwave is meant to be better than this!

4

One would hope… but I’ve certainly had this kind of issue before.
If you believe it to be a software issue, you can rule that out by plugging your Z-Wave stick into your workstation and running the Z-Wave PC Controller.

It’ll let you send commands to your dimmer directly (at least on/off).
It’ll also let you directly exclude and re-include, if that should prove necessary.

You could also plug the Z-Wave stick into your laptop and do the same thing, that way it’s portable and you could try it right next to the device.

I’ve seen NEO CoolCam Z-Wave devices get worse with age (range decreases until they finally die in a puff of smoke) but Aeotec makes good stuff as far as I know.

5

When you say PC controller, do you mean Zensys? I know of no way to send commands to ZWave devices other than using OH2.

6

No, I mean the free Windows app from SiliconLabs which the entire thread I linked to is about. That light blue text is a link :). Scroll to post 10 for the good stuff.

1 Like
7

What binding version are you on?

8

Gday Mark, latest and greatest - 2.5 snapshot as of 3 days ago…

9

Hmm. That’s strange. Before you restarted the binding, did you try just deleting the thing, then running discovery again?

10

Hi Mark, i didnt. But next time Ill do that!

11

Yeah, I sometimes find that delete/rediscover will resolve that problem. And, it’s better than having to restart the binding, especially with a big network…

12

Wonder why this occurs…