Remove a ghost Z-Wave Node from HABmin

mhilbush · March 3, 2019, 3:34pm

I can’t recall if the Zensys tool shows the actual bytes that are sent. Currently, I have a ghost node that I need to remove from the controller. It’s in my production system (~100 nodes), which I don’t shutdown very often. Next time I shut it down, I’ll remove the node with the Zensys tool and report back – unless someone can get to it before me.

I suspect there’s a difference between what the binding does versus the Zensys tool. I’ve never been able to remove a node from the controller using the binding (at least not that I can remember), but have done so frequently with the Zensys tool.

FTR, this is the procedure I follow.

Kim_Andersen · March 3, 2019, 6:01pm

Habmin kan remove nodes fine, but the node has to be online/connectable. This is why Habmin cant remove ghost nodes.

What I hate most about Zensys tools is, that i have to take my z-wave stick out of my Rpi, and plug it in to my windows. to remove the ghost nodes. If I had a simular interface on my Rpi, it wouldnt be a problem.

mhilbush · March 3, 2019, 6:24pm

Right. So, my preference would be for the binding to work the way Zensys works. If we can figure out what Zensys sends when you select is node failed and remove failed, then @chris can figure out what the binding is doing differently.

Agree completely!

TheNetStriker · March 3, 2019, 6:25pm

I’ve just tested this again with a non battery node. With this node it didn’t work for some reason, but I was able to see what the Zensys Tool is sending to the controller. Maybe this workarround only works for battery controlled devices or maybe the device has to be absent for some time. Here is a screenshot from the Zensys tool where the packet is shown:

It seemss that only the node id and a sequential number is sent to the controller. The Zensys Tools is .Net based, so I was also able to look at the code using dnspy and there I also found this:

byte[] response = base.SessionLayer.ExecuteRequest(99, new byte[]
{
nodeId,
base.SessionLayer.SequenceNumber
});

Do you know this command and is this already implemented in the ZWave binding?

mhilbush · March 3, 2019, 6:30pm

The procedure described above (which is what I use) is this. Can you see what Zensys is sending for each of the steps 3, 4, and 5?

1. Highlight the node you believe has failed from the top left frame’s node list/table
2. Toggle the “Quene Overrided” checkbox for this selected node (a check should appear)
3. Send a NOP (i.e. no operation) command by selecting the exclamation mark from the tools menu
4. Check to see if the node is failed by selecting the “is node failed” icon from the tools menu. If it has failed, you should see a message stating it has failed in the lower right frame (i.e. log actions tab)
5. Select the “remove failed” icon from the tools menu
Note: If uncertain which icon from the tools menu corresponds to a particular action, hoover your mouse over each to receive a “tool tip” message specifying the corresponding action.

chris · March 3, 2019, 6:30pm

You’re getting mixed up between removing dead nodes, and excluding nodes.

I agree, and that’s why I think it should be doing. However, I’m only going on the poor ZWave documentation. If someone can get me a dump of the data that is sent, then we can see what is really sent.

chris · March 3, 2019, 6:37pm

So here’s what the binding does -:

To set the failed node -:

    public void requestSetFailedNode(int nodeId) {
        enqueue(new ReplaceFailedNodeMessageClass().doRequest(nodeId));
    }

        ReplaceFailedNode(0x63, true, true, false), // Remove a failed node from the controller's list (?)

0x63 == 99, so this is the same as described above -:

Then to remove the failed node -:

    public void requestRemoveFailedNode(int nodeId) {
        enqueue(new RemoveFailedNodeMessageClass().doRequest(nodeId));
    }

        RemoveFailedNodeID(0x61, true, true, false), // Mark a specified node id as failed

The binding does this often - if the node is failed, then it should be added to the failed node list. This should do the same thing as the “set to failed node list” command - at least that’s what the ZWave documentation states.

Again, this is what is done.

So, from the above, so far, it looks like the binding does the same thing as the ZenSys tool? Or am I missing something?

I’m open to suggestions

mhilbush · March 3, 2019, 6:43pm

If @TheNetStriker has already whacked his ghost node, I’ll run through steps 3-5 with my ghost node.

TheNetStriker · March 3, 2019, 6:44pm

Yes it seems as this is doing exacly the same thing. I also did a packet capture and found this:

7438 0x00000005 7 unsigned char[7] Payload { 1, 5, 0, 99, 65… } 03.03.2019 18:52:50
00000000 01 05 00 63 41 10 c8 …cA…

Does maybe the ZWave binding doesn’t send this command if the node is not reachable? In habmin I used to get an error when sending the command to a dead node.

chris · March 3, 2019, 6:47pm

It will send the command no-matter what.

mhilbush · March 3, 2019, 6:57pm

Here’s what I get in Zensys for steps 3 (NOP), 4 (isFailed), and 5 (removeFailed).

Node number is 111.

Capture

chris · March 3, 2019, 7:03pm

Thanks - is it possible to get the full list of bytes sent, or is this all it will show?

I can see one error which might explain things, but it would be good to see what is actually sent? (or I can guess of course ).

mhilbush · March 3, 2019, 7:04pm

That’s all it showed. I don’t use that app enough to know if there’s a way to get all the data.

chris · March 3, 2019, 7:07pm

No - I think that is just an alternative way to get it into the failed nodes list.

mhilbush · March 3, 2019, 7:09pm

BTW, I don’t know if the NOP is important, or not. I always follow the steps religiously, as getting rid of these ghost nodes is not something I’m willing to experiment with using my production stick.

I have a test stick, but it’s in another location; otherwise, I’d experiment as much as necessary…

chris · March 3, 2019, 7:15pm

So as far as I can see, I’m sending the same thing as shown above in the ZenSys tool…

The ZWave docs state -:

And this is what I’m sending -:

        return new ZWaveTransactionMessageBuilder(SerialMessageClass.RemoveFailedNodeID).withPayload(nodeId, 1).build();

        RemoveFailedNodeID(0x61, true, true, false), // Mark a specified node id as failed

This should send 0x61, node Id, 0x01 which as far as I can see is the same as sent by ZenSys (except in the log above the funcId is 0x04, but that’s just an Id used to correlate the response which in this case is coded to 1 in the binding for historical reasons.

mhilbush · March 3, 2019, 7:27pm

I have a log from when I tried to remove a ghost node using the binding. Gimme a minute and I’ll post that. Maybe it will help shed some light. It’s from a few months ago, so please don’t ask me to describe/explain what I did from the UI…

mhilbush · March 3, 2019, 7:36pm

Here’s the log for node 108 (from one of my 500 old logs files). I’m pretty sure I did a Set as failed followed by a Remove from controller, although there may be other variations in the log as well.

2018-11-25 08:41:41.497 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update received
2018-11-25 08:41:41.497 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update set action_failed to true (Boolean)
2018-11-25 08:41:41.497 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Marking node as having failed.
2018-11-25 08:41:41.498 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Added 6782 to queue - size 1
2018-11-25 08:41:41.498 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:41:41.498 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 6C 01 56 A3 
2018-11-25 08:41:41.498 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 6C 01 56 A3 
2018-11-25 08:41:41.498 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-25 08:41:41.498 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6782: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 86
2018-11-25 08:41:41.499 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-25 08:41:41.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:41.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:41.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6782: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 86
2018-11-25 08:41:41.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-25 08:41:41.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:41.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:41:41.507 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 00 9B 
2018-11-25 08:41:41.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:41:41.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:41:41.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6782: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 86
2018-11-25 08:41:41.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:41:41.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6782: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 86
2018-11-25 08:41:41.507 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:41:41.508 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.
2018-11-25 08:41:41.508 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Remove failed node successfully placed on stack.
2018-11-25 08:41:41.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 6782: Advanced to WAIT_REQUEST
2018-11-25 08:41:41.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: TID 6782: Transaction not completed
2018-11-25 08:41:41.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:41.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:41:45.652 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 61 01 01 9B 
2018-11-25 08:41:45.652 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Request[0], dest=1, callback=1, payload=01 01 
2018-11-25 08:41:45.653 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Request[0], dest=1, callback=1, payload=01 01 
2018-11-25 08:41:45.653 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6782: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 86
2018-11-25 08:41:45.653 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:41:45.653 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6782: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 86
2018-11-25 08:41:45.653 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 6782: (Callback 86)
2018-11-25 08:41:45.653 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - NO callback match! (86 <> 1)
2018-11-25 08:41:45.653 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Request[0], dest=1, callback=1, payload=01 01 
2018-11-25 08:41:45.653 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE {}: transaction not correlated for RemoveFailedNodeMessageClass
2018-11-25 08:41:45.654 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:45.654 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:41:46.508 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 255: TID 6782: Timeout at state WAIT_REQUEST. 3 retries remaining.
2018-11-25 08:41:46.509 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - TID 6782: Transaction is current transaction, so clearing!!!!!
2018-11-25 08:41:46.509 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6782: Transaction CANCELLED
2018-11-25 08:41:46.509 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6782 CANCELLED
2018-11-25 08:41:46.509 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:41:49.099 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update received
2018-11-25 08:41:49.100 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update set action_remove to true (Boolean)
2018-11-25 08:41:49.100 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Marking node as having failed.
2018-11-25 08:41:49.100 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Added 6783 to queue - size 1
2018-11-25 08:41:49.100 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:41:49.100 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 6C 01 57 A2 
2018-11-25 08:41:49.100 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 6C 01 57 A2 
2018-11-25 08:41:49.100 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-25 08:41:49.100 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6783: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 87
2018-11-25 08:41:49.101 [DEBUG] [al.protocol.serialmessage.IsFailedNodeMessageClass] - NODE 108: Requesting IsFailedNode status from controller.
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Added 6784 to queue - size 1
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:41:49.101 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6783: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 87
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:49.101 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:41:49.102 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 08 93 
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6783: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 87
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6783: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 87
2018-11-25 08:41:49.102 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:41:49.102 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.
2018-11-25 08:41:49.102 [ERROR] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Remove failed node failed as node not found
2018-11-25 08:41:49.102 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6783: Transaction COMPLETED
2018-11-25 08:41:49.102 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Got an event from Z-Wave network: ZWaveNetworkEvent
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 2ms
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: TID 6783: Transaction completed
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6783 DONE
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:41:49.102 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 6C F5 
2018-11-25 08:41:49.102 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 6C F5 
2018-11-25 08:41:49.102 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-25 08:41:49.102 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6784: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:41:49.103 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-25 08:41:49.103 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:49.103 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:49.103 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6784: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:41:49.103 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-25 08:41:49.103 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:49.103 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:41:49.104 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 00 98 
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6784: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6784: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:41:49.104 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:41:49.104 [DEBUG] [al.protocol.serialmessage.IsFailedNodeMessageClass] - NODE 108: Is currently marked as healthy by the controller
2018-11-25 08:41:49.104 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2018-11-25 08:41:49.104 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Setting ONLINE
2018-11-25 08:41:49.104 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 108: Node Status event - Node is ALIVE
2018-11-25 08:41:49.104 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 108: Node is ALIVE. Init stage is REQUEST_NIF.
2018-11-25 08:41:49.104 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2018-11-25 08:41:49.104 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Setting ONLINE
2018-11-25 08:41:49.104 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 108: Node Status event - Node is ALIVE
2018-11-25 08:41:49.104 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6784: Transaction COMPLETED
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 2ms
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: TID 6784: Transaction completed
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6784 DONE
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:49.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:41:55.017 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update received
2018-11-25 08:41:55.018 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update set action_failed to true (Boolean)
2018-11-25 08:41:55.018 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Marking node as having failed.
2018-11-25 08:41:55.018 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Added 6785 to queue - size 1
2018-11-25 08:41:55.018 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:41:55.018 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 6C 01 58 AD 
2018-11-25 08:41:55.019 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 6C 01 58 AD 
2018-11-25 08:41:55.019 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-25 08:41:55.019 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6785: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 88
2018-11-25 08:41:55.019 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-25 08:41:55.019 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6785: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 88
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:41:55.020 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 08 93 
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6785: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 88
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6785: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 88
2018-11-25 08:41:55.020 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:41:55.020 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.
2018-11-25 08:41:55.020 [ERROR] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Remove failed node failed as node not found
2018-11-25 08:41:55.020 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6785: Transaction COMPLETED
2018-11-25 08:41:55.020 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Got an event from Z-Wave network: ZWaveNetworkEvent
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 1ms
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: TID 6785: Transaction completed
2018-11-25 08:41:55.020 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6785 DONE
2018-11-25 08:41:55.021 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:41:55.021 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:42:07.025 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 25 06 31 05 03 0A 00 0F E6 
2018-11-25 08:42:07.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=37, callback=0, payload=00 25 06 31 05 03 0A 00 0F 
2018-11-25 08:42:07.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=37, callback=0, payload=00 25 06 31 05 03 0A 00 0F 
2018-11-25 08:42:07.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-11-25 08:42:07.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 37: Application Command Request (ALIVE:DONE)
2018-11-25 08:42:07.026 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 37: resetResendCount initComplete=true isDead=false
2018-11-25 08:42:07.026 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 37: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2018-11-25 08:42:07.026 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 37: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL
2018-11-25 08:42:07.026 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 37: Received COMMAND_CLASS_SENSOR_MULTILEVEL V8 SENSOR_MULTILEVEL_REPORT
2018-11-25 08:42:07.026 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 37: Sensor Type = Luminance(3), Scale = 1
2018-11-25 08:42:07.026 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 37: Sensor Value = 15
2018-11-25 08:42:07.026 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 37: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-11-25 08:42:07.026 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 37: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 15
2018-11-25 08:42:07.026 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 37: Updating channel state zwave:device:zstick:node37:sensor_luminance to 15 % [QuantityType]
2018-11-25 08:42:07.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 37: Commands processed 1.
2018-11-25 08:42:07.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 37: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@25fa41a1.
2018-11-25 08:42:07.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-25 08:42:07.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-25 08:42:07.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:07.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:42:09.896 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update received
2018-11-25 08:42:09.896 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update set action_failed to true (Boolean)
2018-11-25 08:42:09.897 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Marking node as having failed.
2018-11-25 08:42:09.897 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Added 6786 to queue - size 1
2018-11-25 08:42:09.897 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:42:09.897 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 6C 01 59 AC 
2018-11-25 08:42:09.897 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 6C 01 59 AC 
2018-11-25 08:42:09.897 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-25 08:42:09.897 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6786: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 89
2018-11-25 08:42:09.898 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-25 08:42:09.898 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:42:09.898 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:42:09.898 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6786: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 89
2018-11-25 08:42:09.898 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-25 08:42:09.898 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:09.898 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:42:09.899 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 08 93 
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6786: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 89
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6786: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 89
2018-11-25 08:42:09.899 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:42:09.899 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.
2018-11-25 08:42:09.899 [ERROR] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Remove failed node failed as node not found
2018-11-25 08:42:09.899 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6786: Transaction COMPLETED
2018-11-25 08:42:09.899 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Got an event from Z-Wave network: ZWaveNetworkEvent
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 2ms
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: TID 6786: Transaction completed
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6786 DONE
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:09.899 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:42:11.510 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 44 03 80 03 23 15 
2018-11-25 08:42:11.510 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=68, callback=0, payload=00 44 03 80 03 23 
2018-11-25 08:42:11.511 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=68, callback=0, payload=00 44 03 80 03 23 
2018-11-25 08:42:11.511 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-11-25 08:42:11.511 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 68: Application Command Request (ALIVE:DONE)
2018-11-25 08:42:11.511 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 68: resetResendCount initComplete=true isDead=false
2018-11-25 08:42:11.511 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 68: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
2018-11-25 08:42:11.511 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 68: SECURITY not supported
2018-11-25 08:42:11.511 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 68: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
2018-11-25 08:42:11.511 [DEBUG] [nal.protocol.commandclass.ZWaveBatteryCommandClass] - NODE 68: Battery report value = 35
2018-11-25 08:42:11.511 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 68: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-11-25 08:42:11.511 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 68: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BATTERY, value = 35
2018-11-25 08:42:11.512 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 68: Updating channel state zwave:device:zstick:node68:battery-level to 35 [DecimalType]
2018-11-25 08:42:11.512 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 68: Commands processed 1.
2018-11-25 08:42:11.512 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 68: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@83770a2.
2018-11-25 08:42:11.512 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-25 08:42:11.512 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-25 08:42:11.512 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:11.512 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:42:14.189 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update received
2018-11-25 08:42:14.189 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Configuration update set action_remove to true (Boolean)
2018-11-25 08:42:14.190 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Marking node as having failed.
2018-11-25 08:42:14.190 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Added 6787 to queue - size 1
2018-11-25 08:42:14.190 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:42:14.190 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 6C 01 5A AF 
2018-11-25 08:42:14.190 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 6C 01 5A AF 
2018-11-25 08:42:14.190 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-25 08:42:14.190 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6787: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 90
2018-11-25 08:42:14.191 [DEBUG] [al.protocol.serialmessage.IsFailedNodeMessageClass] - NODE 108: Requesting IsFailedNode status from controller.
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Added 6788 to queue - size 1
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:42:14.191 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6787: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 90
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:14.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:42:14.191 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 08 93 
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6787: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 90
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6787: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 90
2018-11-25 08:42:14.192 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2018-11-25 08:42:14.192 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.
2018-11-25 08:42:14.192 [ERROR] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 108: Remove failed node failed as node not found
2018-11-25 08:42:14.192 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6787: Transaction COMPLETED
2018-11-25 08:42:14.192 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 108: Got an event from Z-Wave network: ZWaveNetworkEvent
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 2ms
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: TID 6787: Transaction completed
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6787 DONE
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-25 08:42:14.192 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 6C F5 
2018-11-25 08:42:14.192 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 6C F5 
2018-11-25 08:42:14.192 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-25 08:42:14.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6788: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:42:14.193 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6788: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-25 08:42:14.193 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 00 98 
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 6788: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-25 08:42:14.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 6788: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-11-25 08:42:14.193 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=00 
2018-11-25 08:42:14.194 [DEBUG] [al.protocol.serialmessage.IsFailedNodeMessageClass] - NODE 108: Is currently marked as healthy by the controller
2018-11-25 08:42:14.194 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 6788: Transaction COMPLETED
2018-11-25 08:42:14.194 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 2ms
2018-11-25 08:42:14.194 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: TID 6788: Transaction completed
2018-11-25 08:42:14.194 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6788 DONE
2018-11-25 08:42:14.194 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-25 08:42:14.194 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

chris · March 3, 2019, 7:56pm

Looks ok to me - just as above -:

At least one reason why it didn’t work is that the device was showing as healthy -:

ie the response is 0, which is FALSE, which means the device is not in the failed nodes list. If it’s not in the failed node list, it can’t be removed.

I would have expected to have seen the set failed node before trying to remove the device, but that’s now shown in this log at least.

mhilbush · March 3, 2019, 8:03pm

I’m a bit out of my depth on this, but… What’s the difference between action_failed and action_remove? They seem to be doing the same thing (i.e. sending the RemoveFailedNodeID).

ZWave%20Log%20Viewer%202019-03-03%2015-00-22