Aeon Labs ZW056 doorbell

The nightly build is on cloudbees -: https://openhab.ci.cloudbees.com/

So I downloaded this: https://openhab.ci.cloudbees.com/job/openHAB-Distribution/lastSuccessfulBuild/artifact/distributions/openhab-offline/target/openhab-offline-2.0.0-SNAPSHOT.zip

unzipped it, found org.openhab.binding.zwave-2.0.0-SNAPSHOT.jar and replaced my previous version (1.9.0) in my addons folder. I now have a non-working system (never comes online in habmin). Nothing interesting shows up on openhab.log.

You have downloaded the OH2 version - you need to download the OH1 version if your system is OH1. The OH1 binding is in the OH1-Addons folder.

Oh. Right. Of course. Thanks.

I mistakenly assumed openhab-* was OH1 and openhab2-* was OH2:

	openhab-offline-2.0.0-SNAPSHOT.zip	150.98 MB	 view
	openhab2-offline-2.0.0-SNAPSHOT.deb	150.49 MB	 view

Unfortunately with the latest zwave binding build, found here: https://openhab.ci.cloudbees.com/job/openHAB1-Addons/lastBuild/org.openhab.binding$org.openhab.binding.zwave/artifact/org.openhab.binding/org.openhab.binding.zwave/1.9.0-SNAPSHOT/org.openhab.binding.zwave-1.9.0-SNAPSHOT.jar

I still get the retries like I had seen before:

2016-08-15 22:57:08.576 [DEBUG] [ZWaveConfigurationCommandClass:183 ]- NODE 8: Creating new message for application command CONFIGURATIONCMD_SET
2016-08-15 22:57:08.578 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 8: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-08-15 22:57:08.581 [DEBUG] [ZWaveConfigurationCommandClass:160 ]- NODE 8: Creating new message for application command CONFIGURATIONCMD_GET
2016-08-15 22:57:08.582 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 8: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-08-15 22:57:08.583 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0C 00 13 08 05 70 04 06 01 05 25 32 8C
2016-08-15 22:57:08.595 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 22:57:08.618 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 50, Status = Transmission complete and ACK received(0)
2016-08-15 22:57:08.621 [DEBUG] [WaveController$ZWaveSendThread:1364]- NODE 8: Response processed after 37ms/2405ms.
2016-08-15 22:57:08.623 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 33 88
2016-08-15 22:57:08.634 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 22:57:09.139 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 51, Status = Transmission complete and ACK received(0)
2016-08-15 22:57:13.624 [ERROR] [WaveController$ZWaveSendThread:1347]- NODE 8: Timeout while sending message. Requeueing - 2 attempts left!
2016-08-15 22:57:13.625 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ]- NODE 8: Got an error while sending data. Resending message.
2016-08-15 22:57:13.630 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 35 8E
2016-08-15 22:57:13.644 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 22:57:13.705 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 53, Status = Transmission complete and ACK received(0)
2016-08-15 22:57:18.632 [ERROR] [WaveController$ZWaveSendThread:1347]- NODE 8: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-15 22:57:18.633 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ]- NODE 8: Got an error while sending data. Resending message.
2016-08-15 22:57:18.638 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 36 8D
2016-08-15 22:57:18.652 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 22:57:18.711 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 54, Status = Transmission complete and ACK received(0)
2016-08-15 22:57:23.639 [ERROR] [WaveController$ZWaveSendThread:1347]- NODE 8: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-15 22:57:23.640 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ]- NODE 8: Got an error while sending data. Resending message.
2016-08-15 22:57:23.650 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 37 8C
2016-08-15 22:57:23.664 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 22:57:23.724 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 55, Status = Transmission complete and ACK received(0)
2016-08-15 22:57:28.652 [WARN ] [WaveController$ZWaveSendThread:1355]- NODE 8: Too many retries. Discarding message: Message: class = SendData (0x13), type = Request (0x00), payload = 08 03 70 05 06

Any ideas?

Do I have to reset or reload or re-initialize the node or something to take on the new config parameters or something? I tried deleting node8.xml from my /etc/zwave directory but it never came back/regenerated. Anything else I can check on my end?

The full log (not just “NODE 8”):

2016-08-15 23:09:32.452 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:32.452 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:32.454 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-08-15 23:09:32.455 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 04 01 13 01 E8 
2016-08-15 23:09:32.456 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-08-15 23:09:32.456 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 6: Sent Data successfully placed on stack.
2016-08-15 23:09:32.467 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 07 00 13 A1 00 00 02 48 
2016-08-15 23:09:32.469 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:32.469 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:32.471 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 09 00 13 A1 00 00 02 00 00 46 
2016-08-15 23:09:32.472 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 09 00 13 A1 00 00 02 00 00 46 
2016-08-15 23:09:32.473 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Request (0x00), payload = A1 00 00 02 
2016-08-15 23:09:32.474 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 6: SendData Request. CallBack ID = 161, Status = Transmission complete and ACK received(0)
2016-08-15 23:09:32.475 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:66  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 06 03 32 01 10 
2016-08-15 23:09:32.476 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:67  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = A1 00 00 02 
2016-08-15 23:09:32.477 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2016-08-15 23:09:32.481 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 14 00 04 00 06 0E 32 02 21 74 00 2A 49 FA 00 00 00 2F 21 F8 ED 
2016-08-15 23:09:32.484 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:32.484 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:32.487 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 14 00 04 00 06 0E 32 02 21 74 00 2A 49 FA 00 00 00 2F 21 F8 ED 
2016-08-15 23:09:32.488 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 14 00 04 00 06 0E 32 02 21 74 00 2A 49 FA 00 00 00 2F 21 F8 ED 
2016-08-15 23:09:32.490 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 06 0E 32 02 21 74 00 2A 49 FA 00 00 00 2F 21 F8 
2016-08-15 23:09:32.491 [DEBUG] [ApplicationCommandMessageClass:40  ]- NODE 6: Application Command Request (ALIVE:DONE)
2016-08-15 23:09:32.492 [DEBUG] [ApplicationCommandMessageClass:58  ]- NODE 6: Incoming command class METER
2016-08-15 23:09:32.492 [DEBUG] [z.i.p.c.ZWaveMeterCommandClass:109 ]- NODE 6: Received Meter Request
2016-08-15 23:09:32.494 [DEBUG] [z.i.p.c.ZWaveMeterCommandClass:157 ]- NODE 6: Meter: Type=Electric(1), Scale=W(2), Value=2771.45
2016-08-15 23:09:32.495 [DEBUG] [b.z.i.protocol.ZWaveController:648 ]- Notifying event listeners: ZWaveMeterValueEvent
2016-08-15 23:09:32.495 [DEBUG] [.z.internal.ZWaveActiveBinding:449 ]- ZwaveIncomingEvent
2016-08-15 23:09:32.496 [DEBUG] [.z.internal.ZWaveActiveBinding:466 ]- NODE 6: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 2771.45
2016-08-15 23:09:32.508 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:66  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 06 03 32 01 10 
2016-08-15 23:09:32.510 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:67  ]- Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 06 0E 32 02 21 74 00 2A 49 FA 00 00 00 2F 21 F8 
2016-08-15 23:09:32.510 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]- Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2016-08-15 23:09:32.511 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74  ]-          transaction complete!
2016-08-15 23:09:32.512 [DEBUG] [b.z.i.protocol.ZWaveController:648 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-08-15 23:09:32.512 [DEBUG] [.z.internal.ZWaveActiveBinding:449 ]- ZwaveIncomingEvent
2016-08-15 23:09:32.513 [DEBUG] [WaveController$ZWaveSendThread:1364]- NODE 6: Response processed after 71ms/2820ms.
2016-08-15 23:09:34.753 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 9: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:34.754 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 10: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:34.756 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 11: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:34.757 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 12: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:35.435 [DEBUG] [ZWaveConfigurationCommandClass:183 ]- NODE 8: Creating new message for application command CONFIGURATIONCMD_SET
2016-08-15 23:09:35.436 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 8: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-08-15 23:09:35.437 [DEBUG] [b.z.i.protocol.ZWaveController:947 ]- Callback ID = 162
2016-08-15 23:09:35.438 [DEBUG] [b.z.i.protocol.ZWaveController:632 ]- Enqueueing message. Queue length = 1
2016-08-15 23:09:35.438 [DEBUG] [WaveController$ZWaveSendThread:1241]- Took message from queue for sending. Queue length = 0
2016-08-15 23:09:35.439 [DEBUG] [ZWaveConfigurationCommandClass:160 ]- NODE 8: Creating new message for application command CONFIGURATIONCMD_GET
2016-08-15 23:09:35.440 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 0C 00 13 08 05 70 04 06 01 05 25 A2 1C 
2016-08-15 23:09:35.440 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 8: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-08-15 23:09:35.441 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0C 00 13 08 05 70 04 06 01 05 25 A2 1C 
2016-08-15 23:09:35.441 [DEBUG] [b.z.i.protocol.ZWaveController:947 ]- Callback ID = 163
2016-08-15 23:09:35.442 [DEBUG] [b.z.i.protocol.ZWaveController:632 ]- Enqueueing message. Queue length = 1
2016-08-15 23:09:35.451 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 04 01 13 01 E8 
2016-08-15 23:09:35.452 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:35.452 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:35.453 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-08-15 23:09:35.454 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 04 01 13 01 E8 
2016-08-15 23:09:35.454 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-08-15 23:09:35.454 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 23:09:35.471 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 07 00 13 A2 00 00 03 4A 
2016-08-15 23:09:35.472 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:35.472 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:35.473 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 09 00 13 A2 00 00 03 00 00 44 
2016-08-15 23:09:35.474 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 09 00 13 A2 00 00 03 00 00 44 
2016-08-15 23:09:35.474 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Request (0x00), payload = A2 00 00 03 
2016-08-15 23:09:35.475 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 162, Status = Transmission complete and ACK received(0)
2016-08-15 23:09:35.476 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:66  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 08 05 70 04 06 01 05 
2016-08-15 23:09:35.476 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:67  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = A2 00 00 03 
2016-08-15 23:09:35.476 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]- Checking transaction complete: class=SendData, expected=SendData, cancelled=false
2016-08-15 23:09:35.477 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74  ]-          transaction complete!
2016-08-15 23:09:35.477 [DEBUG] [b.z.i.protocol.ZWaveController:648 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-08-15 23:09:35.477 [DEBUG] [.z.internal.ZWaveActiveBinding:449 ]- ZwaveIncomingEvent
2016-08-15 23:09:35.478 [DEBUG] [WaveController$ZWaveSendThread:1364]- NODE 8: Response processed after 37ms/2820ms.
2016-08-15 23:09:35.478 [DEBUG] [WaveController$ZWaveSendThread:1241]- Took message from queue for sending. Queue length = 0
2016-08-15 23:09:35.479 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 0A 00 13 08 03 70 05 06 25 A3 18 
2016-08-15 23:09:35.479 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 A3 18 
2016-08-15 23:09:35.488 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 04 01 13 01 E8 
2016-08-15 23:09:35.489 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:35.489 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:35.490 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-08-15 23:09:35.490 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 04 01 13 01 E8 
2016-08-15 23:09:35.490 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-08-15 23:09:35.491 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 23:09:36.796 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 07 00 13 A3 00 00 83 CB 
2016-08-15 23:09:36.798 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:36.798 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:36.800 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 09 00 13 A3 00 00 83 00 00 C5 
2016-08-15 23:09:36.801 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 09 00 13 A3 00 00 83 00 00 C5 
2016-08-15 23:09:36.802 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Request (0x00), payload = A3 00 00 83 
2016-08-15 23:09:36.803 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 163, Status = Transmission complete and ACK received(0)
2016-08-15 23:09:36.804 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:66  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 08 03 70 05 06 
2016-08-15 23:09:36.806 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:67  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = A3 00 00 83 
2016-08-15 23:09:36.806 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2016-08-15 23:09:40.480 [ERROR] [WaveController$ZWaveSendThread:1347]- NODE 8: Timeout while sending message. Requeueing - 2 attempts left!
2016-08-15 23:09:40.481 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ]- NODE 8: Got an error while sending data. Resending message.
2016-08-15 23:09:40.487 [DEBUG] [b.z.i.protocol.ZWaveController:947 ]- Callback ID = 164
2016-08-15 23:09:40.488 [DEBUG] [b.z.i.protocol.ZWaveController:632 ]- Enqueueing message. Queue length = 1
2016-08-15 23:09:40.489 [DEBUG] [WaveController$ZWaveSendThread:1241]- Took message from queue for sending. Queue length = 0
2016-08-15 23:09:40.491 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 0A 00 13 08 03 70 05 06 25 A4 1F 
2016-08-15 23:09:40.492 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 A4 1F 
2016-08-15 23:09:40.502 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 04 01 13 01 E8 
2016-08-15 23:09:40.503 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:40.503 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:40.505 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-08-15 23:09:40.506 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 04 01 13 01 E8 
2016-08-15 23:09:40.507 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-08-15 23:09:40.508 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 23:09:40.647 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 07 00 13 A4 00 00 0F 40 
2016-08-15 23:09:40.649 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:40.649 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:40.650 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 09 00 13 A4 00 00 0F 00 00 4E 
2016-08-15 23:09:40.651 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 09 00 13 A4 00 00 0F 00 00 4E 
2016-08-15 23:09:40.652 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Request (0x00), payload = A4 00 00 0F 
2016-08-15 23:09:40.653 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 164, Status = Transmission complete and ACK received(0)
2016-08-15 23:09:40.654 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:66  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 08 03 70 05 06 
2016-08-15 23:09:40.655 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:67  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = A4 00 00 0F 
2016-08-15 23:09:40.656 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2016-08-15 23:09:40.819 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 9: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:40.820 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 10: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:40.821 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 11: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:40.823 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 12: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:42.367 [DEBUG] [.o.b.z.i.c.ZWaveMeterConverter:70  ]- NODE 6: Generating poll message for METER, endpoint 0
2016-08-15 23:09:42.368 [DEBUG] [z.i.p.c.ZWaveMeterCommandClass:283 ]- NODE 6: Creating new message for application command METER_GET
2016-08-15 23:09:42.369 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 6: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-08-15 23:09:42.369 [DEBUG] [b.z.i.protocol.ZWaveController:947 ]- Callback ID = 165
2016-08-15 23:09:42.369 [DEBUG] [b.z.i.protocol.ZWaveController:632 ]- Enqueueing message. Queue length = 1
2016-08-15 23:09:45.493 [ERROR] [WaveController$ZWaveSendThread:1347]- NODE 8: Timeout while sending message. Requeueing - 1 attempts left!
2016-08-15 23:09:45.501 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ]- NODE 8: Got an error while sending data. Resending message.
2016-08-15 23:09:45.502 [DEBUG] [b.z.i.protocol.ZWaveController:947 ]- Callback ID = 166
2016-08-15 23:09:45.503 [DEBUG] [b.z.i.protocol.ZWaveController:632 ]- Enqueueing message. Queue length = 2
2016-08-15 23:09:45.503 [DEBUG] [WaveController$ZWaveSendThread:1241]- Took message from queue for sending. Queue length = 1
2016-08-15 23:09:45.504 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 0A 00 13 08 03 70 05 06 25 A6 1D 
2016-08-15 23:09:45.505 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 A6 1D 
2016-08-15 23:09:45.514 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 04 01 13 01 E8 
2016-08-15 23:09:45.515 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:45.515 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:45.516 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-08-15 23:09:45.517 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 04 01 13 01 E8 
2016-08-15 23:09:45.518 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-08-15 23:09:45.519 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 23:09:45.641 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 07 00 13 A6 00 00 0D 40 
2016-08-15 23:09:45.643 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:45.643 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:45.645 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 09 00 13 A6 00 00 0D 00 00 4E 
2016-08-15 23:09:45.646 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 09 00 13 A6 00 00 0D 00 00 4E 
2016-08-15 23:09:45.647 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Request (0x00), payload = A6 00 00 0D 
2016-08-15 23:09:45.648 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 166, Status = Transmission complete and ACK received(0)
2016-08-15 23:09:45.650 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:66  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 08 03 70 05 06 
2016-08-15 23:09:45.651 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:67  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = A6 00 00 0D 
2016-08-15 23:09:45.652 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2016-08-15 23:09:46.756 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 9: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:46.757 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 10: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:46.758 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 11: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:46.760 [DEBUG] [.z.i.config.ZWaveConfiguration:288 ]- NODE 12: No database entry: Vision Security [ID:2201,Type:2022]
2016-08-15 23:09:50.506 [ERROR] [WaveController$ZWaveSendThread:1347]- NODE 8: Timeout while sending message. Requeueing - 0 attempts left!
2016-08-15 23:09:50.512 [ERROR] [b.z.i.p.s.SendDataMessageClass:158 ]- NODE 8: Got an error while sending data. Resending message.
2016-08-15 23:09:50.513 [DEBUG] [b.z.i.protocol.ZWaveController:947 ]- Callback ID = 167
2016-08-15 23:09:50.513 [DEBUG] [b.z.i.protocol.ZWaveController:632 ]- Enqueueing message. Queue length = 2
2016-08-15 23:09:50.514 [DEBUG] [WaveController$ZWaveSendThread:1241]- Took message from queue for sending. Queue length = 1
2016-08-15 23:09:50.515 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 0A 00 13 08 03 70 05 06 25 A7 1C 
2016-08-15 23:09:50.516 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 70 05 06 25 A7 1C 
2016-08-15 23:09:50.526 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 04 01 13 01 E8 
2016-08-15 23:09:50.528 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:50.528 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:50.530 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-08-15 23:09:50.531 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 04 01 13 01 E8 
2016-08-15 23:09:50.532 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-08-15 23:09:50.533 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-15 23:09:50.673 [DEBUG] [eController$ZWaveReceiveThread:1530]- Receive Message = 01 07 00 13 A7 00 00 10 5C 
2016-08-15 23:09:50.676 [DEBUG] [eController$ZWaveReceiveThread:1446]- Receive queue ADD: Length=1
2016-08-15 23:09:50.676 [DEBUG] [b.z.i.protocol.ZWaveController:1194]- Receive queue TAKE: Length=0
2016-08-15 23:09:50.678 [DEBUG] [o.b.z.i.protocol.SerialMessage:243 ]- Assembled message buffer = 01 09 00 13 A7 00 00 10 00 00 52 
2016-08-15 23:09:50.680 [DEBUG] [b.z.i.protocol.ZWaveController:1195]- Process Message = 01 09 00 13 A7 00 00 10 00 00 52 
2016-08-15 23:09:50.681 [DEBUG] [b.z.i.protocol.ZWaveController:194 ]- Message: class = SendData (0x13), type = Request (0x00), payload = A7 00 00 10 
2016-08-15 23:09:50.682 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 167, Status = Transmission complete and ACK received(0)
2016-08-15 23:09:50.684 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:66  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 08 03 70 05 06 
2016-08-15 23:09:50.685 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:67  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = A7 00 00 10 
2016-08-15 23:09:50.686 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false

Well at least there’s a workable workaround. Instead of issuing one command to play a specific ringtone (why was this changed from a number to a list, btw?), I can issue two commands- one to change the “default ringtone” and one to simply turn the switch on, both of which apparently seem to not cause these timeouts/delays. I then set a timer in my rule to switch off the switch after a certain number of seconds. A little wonky, but workable.

I’ll take another look at this. It might be that the way that this command is sent (ie through the items definition) doesn’t respect the write_only tag.

Actually, I think you’re right - you need to delete the XML file for this node so that the configuration is reloaded. Give that a try and see if it’s any better.

I did delete the node8.xml file. It remained deleted for quite some time, then it seemed to recreate itself when I messed around with habmin a bit.

Yet, under the configuration section, I still only see parameters 2, 5, and 8. I do not see 6. Not sure if this has anything to do with anything or not.

<entry>
  <commandClass>CONFIGURATION</commandClass>
  <configurationCommandClass>
    <version>1</version>
    <instances>1</instances>
    <configParameters>
      <entry>
        <int>2</int>
        <configurationParameter>
          <index>2</index>
          <size>1</size>
          <value>2</value>
          <readOnly>false</readOnly>
          <writeOnly>false</writeOnly>
        </configurationParameter>
      </entry>
      <entry>
        <int>5</int>
        <configurationParameter>
          <index>5</index>
          <size>1</size>
          <value>3</value>
          <readOnly>false</readOnly>
          <writeOnly>false</writeOnly>
        </configurationParameter>
      </entry>
      <entry>
        <int>8</int>
        <configurationParameter>
          <index>8</index>
          <size>1</size>
          <value>1</value>
          <readOnly>false</readOnly>
          <writeOnly>false</writeOnly>
        </configurationParameter>
      </entry>
    </configParameters>
  </configurationCommandClass>
</entry>

That’s normal - it will get recreated after the device wakes up and the binding has performed all the communications.

That would seem to be correct - we just made parameter 6 write only, so it won’t now be read, and therefore won’t be stored in the file.

Have you checked to see if this works now that the XML file has been recreated? Just deleting the XML won’t make any difference - you need to wait for it to complete the re-initialisation, and this means the XML needs to be recreated. In your earlier post, you said it never came back, so I assume the earlier test was before the initialisation was complete?

Yes, I checked just now. I still get the retries even after the node8.xml is regenerated.

I’ve found a bug that might be a reason for the issue - let’s try again tomorrow… Once you’ve upgraded, delete the XML and restart…

Yes, I think that did it!

2016-08-16 23:19:10.928 [DEBUG] [ZWaveConfigurationCommandClass:183 ]- NODE 8: Creating new message for application command CONFIGURATIONCMD_SET
2016-08-16 23:19:10.929 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 8: Creating empty message of class = SendData (0x13), type = Request (0x00)
**2016-08-16 23:19:10.932 [DEBUG] [ZWaveConfigurationCommandClass:155 ]- NODE 8: CONFIGURATIONCMD_GET ignored for parameter 6 - parameter is write only**
2016-08-16 23:19:10.935 [DEBUG] [WaveController$ZWaveSendThread:1301]- NODE 8: Sending REQUEST Message = 01 0C 00 13 08 05 70 04 06 01 05 25 85 3B
2016-08-16 23:19:10.947 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 8: Sent Data successfully placed on stack.
2016-08-16 23:19:10.965 [DEBUG] [b.z.i.p.s.SendDataMessageClass:73  ]- NODE 8: SendData Request. CallBack ID = 133, Status = Transmission complete and ACK received(0)
2016-08-16 23:19:10.968 [DEBUG] [WaveController$ZWaveSendThread:1364]- NODE 8: Response processed after 32ms/424ms.

Great - glad it’s working. :grinning:

Yes, thanks for all your help!

Is the fix that was mentioned in this thread now included in the zwave binding? I’m trying to use this device and am also experiencing the multiple plays issue. When my test rule fires (which was calling the basic switch_binary item I created, without parameters), or when I flip the switch in HABmin to test, the device plays the sound several times in quick succession. Any help would be appreciated!

Yes - the PR is referenced above.

What version of the binding are you using?

Thanks Chris! I’m using org.openhab.binding.zwave-2.1.0-SNAPSHOT.jar

The item I created for the device is:

Switch alert_speaker_downhall "Downstairs Speaker" <speaker> {channel="zwave:device:e7beb898:node11:switch_binary"}

When I toggle the ON switch in HABmin, the sound starts about 3 times in quick succession before playing the entire sound to completion.

Ok - I guess this is the development version or is this a very old pre-release of the 2.1 binding? If it’s the development version, this version doesn’t perform any retries.

I don’t think there’s any fix for the retries if the controller is doing them. While the binding itself doesn’t currently perform any retry - but the stick does. The stick will perform 3 retries before it signals a failure back to the binding and I guess this is what you are seeing. Presumably the link is asymmetric and the responses aren’t coming back to the controller (just a guess really).

This was my suspicion as well - Seems to me that the device itself should be equipped to handle these retries by disregarding them? The binding i’m using is your security binding that’s one version back I believe. I’m running the distribution 2.1 release and the aeotec z-stick Gen 5. I guess I"m struggling to see how others can be acceptably using this device if it behaves this way.