Heiman HS1SA smoke sensor won't finish initialization

sbholmes · June 13, 2018, 11:51am

Still using OH1 but have the latest snapshot of the zwave binding, and i’ve added the XML for the smoke detector from the database to the jar as I have with other devices.
https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/530?layout=openhab1

Looks like initialization/node advancer gets stuck on MANUFACTURER_SPECIFIC_GET. Can upload full logs elsewhere if that helps, below is just some bits that may help. I’ve excluded and re-included the device many times, and after including have sat pressing the wakeup button over and over to try and get it to finish initialization. It has managed twice in maybe 30 attempts to get past MANUFACTURER, but the first time I’d not added the device XML to the database so it was unrecognised, and the second time something else went wrong and the initialization still didn’t complete.

Any help appreciated!

2018-06-13 23:07:19.518 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1162]- NODE 72: Wakeup during initialisation.
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 72: Node advancer - SECURITY_REPORT: queue length(1), free to send(false)
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 72: Node advancer: loop - SECURITY_REPORT try 1: stageAdvanced(false)
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:509 ]- NODE 72: does not support SECURITY_REPORT, proceeding to next stage.
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:994 ]- NODE 72: Node advancer - advancing to DETAILS
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 72: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:525 ]- NODE 72: Node advancer: received RequestNodeInfo
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:994 ]- NODE 72: Node advancer - advancing to MANUFACTURER
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 72: Node advancer: loop - MANUFACTURER try 0: stageAdvanced(true)
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:547 ]- NODE 72: Node advancer: MANUFACTURER - send ManufacturerSpecific
2018-06-13 23:07:19.519 [DEBUG] [nufacturerSpecificCommandClass:105 ]- NODE 72: Creating new message for command MANUFACTURER_SPECIFIC_GET
2018-06-13 23:07:19.519 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-06-13 23:07:19.519 [DEBUG] [b.z.i.protocol.ZWaveController:976 ]- Callback ID = 118
2018-06-13 23:07:19.519 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 29
2018-06-13 23:07:19.519 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 72: Node advancer - queued packet. Queue length is 1

2018-06-13 23:07:20.519 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:544 ]- NODE 72: No more messages, go back to sleep
2018-06-13 23:07:20.519 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:218 ]- NODE 72: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2018-06-13 23:07:20.519 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00)

2018-06-13 23:07:23.102 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 84 08 25 74 72 

2018-06-13 23:07:24.650 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 72: Sent Data successfully placed on stack.

2018-06-13 23:07:25.182 [DEBUG] [ApplicationCommandMessageClass:122 ]- NODE 72: Transaction not completed: node address inconsistent.  lastSent=72, incoming=255

2018-06-13 23:07:25.203 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 72: SendData Request. CallBack ID = 116, Status = Transmission complete, no ACK received(1)

2018-06-13 23:07:25.203 [DEBUG] [b.z.i.p.s.SendDataMessageClass:109 ]- NODE 72: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK.
2018-06-13 23:07:25.203 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 72: Notifying event listeners: ZWaveTransactionCompletedEvent
2018-06-13 23:07:25.203 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2018-06-13 23:07:25.203 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1138]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(true)
2018-06-13 23:07:25.203 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 72: Node advancer - checking initialisation queue. Queue size 1.
2018-06-13 23:07:25.203 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:409 ]- NODE 72: Went to sleep
2018-06-13 23:07:25.203 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:472 ]- NODE 72: Is sleeping
2018-06-13 23:07:25.203 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 72: Response processed for callback id 116 after 2101ms/4565ms.
2018-06-13 23:07:25.204 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 29
2018-06-13 23:07:25.204 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 72: Putting message SendData in wakeup queue.

2018-06-13 23:07:29.322 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2018-06-13 23:07:29.322 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 6 NIF event during initialisation stage WAIT
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 71 NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 41 NIF event during initialisation stage WAIT
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 38 NIF event during initialisation stage WAIT
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 2 NIF event during initialisation stage DYNAMIC_VALUES
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 71 NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 72 NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1196]- NODE 72: NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 72: Node advancer - MANUFACTURER: queue length(1), free to send(false)
2018-06-13 23:07:29.323 [DEBUG] [b.z.i.protocol.ZWaveController:976 ]- Callback ID = 120
2018-06-13 23:07:29.323 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 72: Putting message SendData in wakeup queue.
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 72: Node advancer - queued packet. Queue length is 1
2018-06-13 23:07:29.323 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ]- NODE 72: Is awake with 2 messages in the wake-up queue.
2018-06-13 23:07:29.323 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 72: Notifying event listeners: ZWaveWakeUpEvent
2018-06-13 23:07:29.323 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1162]- NODE 72: Wakeup during initialisation.
2018-06-13 23:07:29.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 72: Node advancer - MANUFACTURER: queue length(1), free to send(false)
2018-06-13 23:07:29.324 [DEBUG] [b.z.i.protocol.ZWaveController:976 ]- Callback ID = 121
2018-06-13 23:07:29.324 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 27
2018-06-13 23:07:29.324 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 72: Node advancer - queued packet. Queue length is 1

2018-06-13 23:07:39.299 [DEBUG] [.ApplicationUpdateMessageClass:49  ]- NODE 72: Application update request. Node information received.
2018-06-13 23:07:39.299 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:238 ]- NODE 72: Unsupported command class ZWAVE_PLUS_INFO
2018-06-13 23:07:39.299 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:238 ]- NODE 72: Unsupported command class ASSOCIATION_GROUP_INFO
2018-06-13 23:07:39.299 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:238 ]- NODE 72: Unsupported command class DEVICE_RESET_LOCALLY
2018-06-13 23:07:39.299 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:238 ]- NODE 72: Unsupported command class POWERLEVEL
2018-06-13 23:07:39.299 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 72: Notifying event listeners: ZWaveNodeInfoEvent
2018-06-13 23:07:39.299 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2018-06-13 23:07:39.299 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 6 NIF event during initialisation stage WAIT
2018-06-13 23:07:39.299 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 71 NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:39.299 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 41 NIF event during initialisation stage WAIT
2018-06-13 23:07:39.299 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 38 NIF event during initialisation stage WAIT
2018-06-13 23:07:39.299 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 2 NIF event during initialisation stage DYNAMIC_VALUES
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 71 NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1186]- NODE 72: 72 NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1196]- NODE 72: NIF event during initialisation stage MANUFACTURER
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 72: Node advancer - MANUFACTURER: queue length(1), free to send(false)
2018-06-13 23:07:39.300 [DEBUG] [b.z.i.protocol.ZWaveController:976 ]- Callback ID = 130
2018-06-13 23:07:39.300 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 34
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 72: Node advancer - queued packet. Queue length is 1
2018-06-13 23:07:39.300 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ]- NODE 72: Is awake with 1 messages in the wake-up queue.
2018-06-13 23:07:39.300 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 72: Notifying event listeners: ZWaveWakeUpEvent
2018-06-13 23:07:39.300 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1162]- NODE 72: Wakeup during initialisation.
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 72: Node advancer - MANUFACTURER: queue length(1), free to send(false)
2018-06-13 23:07:39.300 [DEBUG] [b.z.i.protocol.ZWaveController:976 ]- Callback ID = 131
2018-06-13 23:07:39.300 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 35
2018-06-13 23:07:39.300 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 72: Node advancer - queued packet. Queue length is 1

2018-06-13 23:07:49.200 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 72: SendData Request. CallBack ID = 132, Status = Transmission complete, no ACK received(1)
2018-06-13 23:07:49.200 [ERROR] [b.z.i.p.s.SendDataMessageClass:142 ]- NODE 72: Node is DEAD. Dropping message.
2018-06-13 23:07:49.200 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 72: Notifying event listeners: ZWaveTransactionCompletedEvent
2018-06-13 23:07:49.200 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2018-06-13 23:07:49.200 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1138]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false)
2018-06-13 23:07:49.200 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 72: Response processed for callback id 132 after 4985ms/4985ms.
2018-06-13 23:07:49.200 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 33
2018-06-13 23:07:49.200 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 09 00 13 48 02 72 04 25 84 78 
2018-06-13 23:07:49.200 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 72 04 25 84 78 

2018-06-13 23:07:51.384 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 72: SendData Request. CallBack ID = 132, Status = Transmission complete, no ACK received(1)
2018-06-13 23:07:51.384 [ERROR] [b.z.i.p.s.SendDataMessageClass:142 ]- NODE 72: Node is DEAD. Dropping message.
2018-06-13 23:07:51.384 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 72: Notifying event listeners: ZWaveTransactionCompletedEvent
2018-06-13 23:07:51.384 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2018-06-13 23:07:51.384 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1138]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false)
2018-06-13 23:07:51.384 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 72: Response processed for callback id 132 after 2184ms/4985ms.
2018-06-13 23:07:51.384 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 32
2018-06-13 23:07:51.384 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 09 00 13 48 02 72 04 25 84 78 
2018-06-13 23:07:51.384 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 72 04 25 84 78 
2018-06-13 23:07:52.932 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 04 01 13 01 E8 
2018-06-13 23:07:52.932 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=1
2018-06-13 23:07:52.932 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2018-06-13 23:07:52.933 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 04 01 13 01 E8 
2018-06-13 23:07:52.933 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 04 01 13 01 E8 
2018-06-13 23:07:52.933 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0
2018-06-13 23:07:52.933 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 72: Sent Data successfully placed on stack.

sbholmes · June 13, 2018, 11:57am

Screenshot from the log viewer of a previous attempt

sbholmes · June 19, 2018, 12:36am

@chris do you have any thoughts on what I can do here?

chris · June 19, 2018, 7:23am

Not really - there doesn’t seem to be any response from any commands sent to the device so there could be a problem with the device receiving, or the stick sending. We do receive the NIF from the device, so the controller can receive data from the device, but it seems there is NO ACK to all messages sent TO the device.

sbholmes · June 20, 2018, 1:03pm

@chris thanks for looking. I just noticed that in the neighbour list for the device it has a non-existent node with a number that’s never been on my network (156). Could this be the problem - might the device be trying to communicate via that node?

I remember reading somewhere in another of your posts that the routing table/neighbour list is maintained by the controller - is there any way of clearing or resetting it short of resetting the controller and losing all my included devices?

I had a similar problem recently with two other devices that used to work normally but developed a strange fault where they only worked when right next to the controller. I later realised that both had non-existent nodes as their only neighbours. I factory reset both devices multiple times, and included them/excluded them several times as well but whenever I looked at them in HABmin they always showed the same neighbours. All other nodes show neighbours that actually exist in my network. Controller is an Aeon Labs Z-stick gen5. Have you seen behaviour like this before - any ideas?

sbholmes · June 23, 2018, 9:59pm

For anyone else reading this thread in the future, the problem was the device was faulty - I swapped it over and the new one finished initialisation perfectly!