2.5.3 Z-wave - thing receives a command, mostly does it, then goes offline

Tags: #<Tag:0x00007f43389de3d8> #<Tag:0x00007f43389de310>

maybe it was just someone speculating that node order played a part in routing preference

Still not helping me get this node online though. It seems to refuse to run through other nodes, and tried hitting the controller directly and struggling.

Are you sure the device is waking up? I have a sensor where the manufacturer’s directions for waking up do not work.
The log should show the device being waked up. I do not recall is debug needs to be turned on for that though.

It’s an aeotec nano switch…as far as I know power devices don’t do a wake up do they?

It’s showing as online now, but any attempt to heal or reinitialise or delete/add don’t seem to resolve it.

Can not start heal as initialisation is not complete (DELETE_SUC_ROUTES)

And I can’t force it to use an intermediary for routing. It’s almost like a need to drop its transmit power just a little, so it can’t see the controller directly.

Have you looked in the debug log to see what is happening? Probably there’s an issue with the device not responding, but maybe it’s something else - the log should provide a lot of insight into what’s happening.

1 Like

2.5.3 was released in March. Those devices in our database were updated early May. Please either upgrade openHAB or, at a minimum, update the Z-Wave binding.

Zigbee and Z-Wave manual install script - Tutorials & Examples - openHAB Community

So I updated to 2.5.6 today. No change to node 19.

I just see a lot of red for it. So this is from a restart. 19 was existing before the restart. But if I delete it and add it, no change. I have all this as a log file. Its 8mb. I’d been playing with moving the controller around, just trying to get it to pick up 19, but nothing seemed to help.



Or maybe this is a better format.

|Time|Node|Entry|
|12:07:17.210|19|Stage advanced to IDENTIFY_NODE|
|12:07:17.252|19|TX REQ IdentifyNode|
|12:07:17.254|19|RX RES IdentifyNode ROUTING_SLAVE POWER_SWITCH_BINARY LISTENING FLIRS250 FLIRS1000 ROUTING BEAMING 0 /128|
|12:07:17.387|19|Stage advanced to PING|
|12:07:17.456|19|TX REQ SendData 1 NO_OPERATION ACK AUTO_ROUTE EXPLORE|
|12:07:17.470|19|RX RES SendData 1 ACCEPTED BY CONTROLLER 0 /128|
|12:07:23.658|19|RX REQ SendData 1 NO ACK after 6202ms 0 /128|
|12:07:23.993|19|TX REQ SendData 2 NO_OPERATION ACK AUTO_ROUTE EXPLORE|
|12:07:24.008|19|RX RES SendData 2 ACCEPTED BY CONTROLLER 0 /128|
|12:07:30.237|19|RX REQ SendData 2 NO ACK after 6244ms 0 /128|
|12:07:30.241|19|TX REQ SendData 3 NO_OPERATION ACK AUTO_ROUTE EXPLORE|
|12:07:30.252|19|RX RES SendData 3 ACCEPTED BY CONTROLLER 0 /128|
|12:07:36.412|19|RX REQ SendData 3 NO ACK after 6171ms 0 /128|
|12:07:36.430|19|Message timeout!|
|12:07:36.431|19|THING STATE OFFLINE|
|12:07:36.432|19|THING STATE OFFLINE|
|12:07:36.470|19|Stage advanced to REQUEST_NIF|
|12:07:36.571|19|TX REQ RequestNodeInfo|
|12:07:36.588|19|RX RES RequestNodeInfo OK 0 /128|
|12:08:03.604|19|TX REQ RequestNodeInfo|
|12:08:08.179|19|TX REQ RequestNodeInfo|
|12:08:08.210|19|RX REQ ApplicationUpdate UPDATE_STATE_NODE_INFO_REQ_FAILED 0 /128|
|12:08:08.442|19|TX REQ RequestNodeInfo|
|12:08:08.454|19|RX RES RequestNodeInfo OK 0 /128|
|12:08:33.460|19|TX REQ RequestNodeInfo|
|12:08:39.202|19|RX RES RequestNodeInfo FAILED 0 /128|
|12:08:39.414|19|RX REQ ApplicationUpdate UPDATE_STATE_NODE_INFO_REQ_FAILED 0 /128|
|12:08:50.368|19|TX REQ RequestNodeInfo|
|12:08:50.379|19|RX RES RequestNodeInfo OK 0 /128|
|12:09:22.022|19|RX REQ ApplicationUpdate UPDATE_STATE_NODE_INFO_REQ_FAILED 0 /128|
|12:09:42.570|19|TX REQ RequestNodeInfo|
|12:09:42.582|19|RX RES RequestNodeInfo OK 0 /128|
|12:10:17.477|19|RX REQ ApplicationUpdate UPDATE_STATE_NODE_INFO_REQ_FAILED 0 /128|
|12:11:02.368|19|TX REQ RequestNodeInfo|
|12:12:48.259|19|TX REQ RequestNodeInfo|
|12:15:56.591|19|TX REQ RequestNodeInfo|
|12:15:56.601|19|RX RES RequestNodeInfo OK 0 /128|
|12:16:28.636|19|RX REQ ApplicationUpdate UPDATE_STATE_NODE_INFO_REQ_FAILED 0 /128|
|12:22:30.821|19|TX REQ RequestNodeInfo|
|12:22:30.832|19|RX RES RequestNodeInfo OK 0 /128|
|12:22:55.836|19|Stage advanced to SECURITY_REPORT|
|12:22:55.836|19|Stage advanced to MANUFACTURER|
|12:22:55.836|19|Stage advanced to APP_VERSION|
|12:22:55.837|19|Stage advanced to DISCOVERY_COMPLETE|
|12:22:55.845|19|Stage advanced to ENDPOINTS|
|12:22:55.845|19|Stage advanced to UPDATE_DATABASE|
|12:22:55.851|19|Stage advanced to STATIC_VALUES|
|12:22:55.852|19|Stage advanced to ASSOCIATIONS|
|12:22:55.852|19|Stage advanced to SET_WAKEUP|
|12:22:55.852|19|Stage advanced to SET_ASSOCIATION|
|12:22:55.852|19|Stage advanced to SET_LIFELINE|
|12:22:55.853|19|Stage advanced to GET_CONFIGURATION|
|12:22:55.853|19|Stage advanced to STATIC_END|
|12:22:55.853|19|Stage advanced to DYNAMIC_VALUES|
|12:22:55.854|19|Stage advanced to DYNAMIC_END|
|12:22:55.855|19|Stage advanced to DONE|
|12:23:45.701|19|RX REQ ApplicationUpdate UPDATE_STATE_NODE_INFO_REQ_FAILED 0 /128|
|12:30:38.198|19|CONFIGURATION UPDATE action_heal true (Boolean)|
|12:30:38.199|19|Stage advanced to HEAL_START|
|12:30:38.200|19|Stage advanced to UPDATE_NEIGHBORS|
|12:30:38.201|19|TX REQ RequestNodeNeighborUpdate|
|12:30:55.281|19|RX RES GetRoutingInfo Found 2 neighbours 0 /128|
|12:30:55.535|19|TX REQ RequestNodeNeighborUpdate|
|12:30:55.652|19|RX REQ RequestNodeNeighborUpdate Neighbor update STARTED 0 /128|
|12:32:08.778|19|RX REQ RequestNodeNeighborUpdate Neighbor update FAILED 0 /128|
|12:32:08.930|19|TX REQ RequestNodeNeighborUpdate|
|12:32:09.048|19|RX REQ RequestNodeNeighborUpdate Neighbor update STARTED 0 /128|
|12:33:22.310|19|RX REQ RequestNodeNeighborUpdate Neighbor update FAILED 0 /128|
|12:33:22.687|19|TX REQ RequestNodeNeighborUpdate|
|12:33:22.803|19|RX REQ RequestNodeNeighborUpdate Neighbor update STARTED 0 /128|
|12:34:36.143|19|RX REQ RequestNodeNeighborUpdate Neighbor update FAILED 0 /128|
|12:34:36.145|19|Message timeout!|
|12:50:51.750|19|THING TYPE zwave:aeon_zw096_00_000|
|12:50:51.779|19|Stage advanced to IDENTIFY_NODE|
|12:50:52.058|19|TX REQ IdentifyNode|
|12:50:52.060|19|RX RES IdentifyNode ROUTING_SLAVE POWER_SWITCH_BINARY LISTENING FLIRS250 FLIRS1000 ROUTING BEAMING 0 /128|
|12:50:52.136|19|Stage advanced to PING|
|12:53:52.319|19|TX REQ SendData 21 NO_OPERATION ACK AUTO_ROUTE EXPLORE|
|12:53:52.326|19|RX RES SendData 21 ACCEPTED BY CONTROLLER 0 /128|
|12:54:07.995|19|RX REQ SendData 21 NO ACK after 15676ms 0 /128|
|12:54:13.199|19|TX REQ SendData 22 NO_OPERATION ACK AUTO_ROUTE EXPLORE|
|12:54:13.201|19|RX RES SendData 22 REJECTED BY CONTROLLER 1 /128|
|12:54:32.786|19|TX REQ SendData 26 NO_OPERATION ACK AUTO_ROUTE EXPLORE|
|12:54:32.794|19|RX RES SendData 26 ACCEPTED BY CONTROLLER 0 /128|
|12:56:40.608|19|CONFIGURATION UPDATE action_heal true (Boolean)|
|12:56:40.608|19|CONFIGURATION UPDATE switchall_mode 255 (BigDecimal)|
|12:56:40.608|19|CONFIGURATION UPDATE binding_cmdrepollperiod 1500 (BigDecimal)|
|12:56:40.608|19|CONFIGURATION UPDATE action_failed false (Boolean)|
|12:56:40.608|19|CONFIGURATION UPDATE group_1 [controller] (ArrayList)|
|12:56:40.609|19|CONFIGURATION UPDATE action_remove false (Boolean)|
|12:56:40.609|19|CONFIGURATION UPDATE binding_pollperiod 86400 (BigDecimal)|
|12:56:40.609|19|CONFIGURATION UPDATE node_id 19 (BigDecimal)|
|12:56:40.609|19|CONFIGURATION UPDATE group_2 [] (EmptyList)|
|13:00:22.112|19|CONFIGURATION UPDATE binding_cmdrepollperiod 15000 (BigDecimal)|
|13:01:07.001|19|CONFIGURATION UPDATE action_heal true (Boolean)|
|13:01:07.001|19|CONFIGURATION UPDATE switchall_mode 255 (BigDecimal)|
|13:01:07.002|19|CONFIGURATION UPDATE binding_cmdrepollperiod 15000 (BigDecimal)|
|13:01:07.002|19|CONFIGURATION UPDATE action_failed false (Boolean)|
|13:01:07.002|19|CONFIGURATION UPDATE group_1 [controller] (ArrayList)|
|13:01:07.002|19|CONFIGURATION UPDATE action_remove false (Boolean)|
|13:01:07.002|19|CONFIGURATION UPDATE binding_pollperiod 86400 (BigDecimal)|
|13:01:07.002|19|CONFIGURATION UPDATE node_id 19 (BigDecimal)|
|13:01:07.002|19|CONFIGURATION UPDATE group_2 [] (EmptyList)|

Ahh this time it’s actually completed figuring out what it is…but seems to be sitting offline…quite often does this. And then it might come back online in an hour or so, and so I’ll try to heal it to get a neighbour update.

So it’s already come back online which is good. So I’ve fired an On Command to it, which just tries and tries and tires.

2020-06-26 18:58:32.699 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Command received zwave:device:a5365e91:node19:switch_binary --> OFF [OnOffType]
2020-06-26 18:58:32.700 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 19: Creating new message for application command SWITCH_BINARY_SET
2020-06-26 18:58:32.701 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY not supported
2020-06-26 18:58:32.701 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2020-06-26 18:58:32.701 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2020-06-26 18:58:32.701 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Added 867 to queue - size 1
2020-06-26 18:58:32.703 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 25 01 00 25 D8 2F
2020-06-26 18:58:32.705 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling initialised at 86400 seconds - start in 15000 milliseconds.
2020-06-26 18:58:32.710 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack.
2020-06-26 18:58:32.710 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 867: Transaction not completed
2020-06-26 18:58:34.147 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Command received zwave:device:a5365e91:node19:switch_binary --> ON [OnOffType]
2020-06-26 18:58:34.147 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 19: Creating new message for application command SWITCH_BINARY_SET
2020-06-26 18:58:34.147 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY not supported
2020-06-26 18:58:34.147 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2020-06-26 18:58:34.147 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2020-06-26 18:58:34.147 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Added 868 to queue - size 1
2020-06-26 18:58:34.148 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling initialised at 86400 seconds - start in 15000 milliseconds.
2020-06-26 18:58:37.711 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 19: TID 867: Timeout at state WAIT_REQUEST. 3 retries remaining.
2020-06-26 18:58:48.730 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 216, Status = Transmission complete, no ACK received(1)
2020-06-26 18:58:48.730 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 18:58:48.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: CANCEL while sending message. Requeueing - 2 attempts left!
2020-06-26 18:58:48.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2020-06-26 18:58:48.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Added 867 to queue - size 2
2020-06-26 18:58:48.731 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 25 01 00 25 D9 2E
2020-06-26 18:58:48.732 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 867: Transaction not completed
2020-06-26 18:58:48.740 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack.
2020-06-26 18:58:48.740 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 867: Transaction not completed
2020-06-26 18:58:49.148 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling...
2020-06-26 18:58:49.148 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling deferred until initialisation complete
2020-06-26 18:58:53.740 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 19: TID 867: Timeout at state WAIT_REQUEST. 2 retries remaining.
2020-06-26 18:59:04.486 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 217, Status = Transmission complete, no ACK received(1)
2020-06-26 18:59:04.487 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 18:59:04.487 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: CANCEL while sending message. Requeueing - 1 attempts left!
2020-06-26 18:59:04.487 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2020-06-26 18:59:04.487 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Added 867 to queue - size 2
2020-06-26 18:59:04.488 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 25 01 00 25 DA 2D
2020-06-26 18:59:04.489 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 867: Transaction not completed
2020-06-26 18:59:04.497 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack.
2020-06-26 18:59:04.497 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 867: Transaction not completed
2020-06-26 18:59:09.497 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 19: TID 867: Timeout at state WAIT_REQUEST. 1 retries remaining.
2020-06-26 18:59:20.306 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 218, Status = Transmission complete, no ACK received(1)
2020-06-26 18:59:20.306 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 18:59:20.306 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Retry count exceeded. Discarding message: TID 867: [CANCELLED] priority=Set, requiresResponse=true, callback: 218
2020-06-26 18:59:20.306 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2020-06-26 18:59:20.306 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Setting OFFLINE
2020-06-26 18:59:20.307 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 19: Node Status event - Node is DEAD
2020-06-26 18:59:20.307 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: Node is DEAD.
2020-06-26 18:59:20.307 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2020-06-26 18:59:20.307 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Setting OFFLINE
2020-06-26 18:59:20.307 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 19: Node Status event - Node is DEAD
2020-06-26 18:59:20.307 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 867: Transaction completed
2020-06-26 18:59:20.308 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: notifyTransactionResponse TID:867 CANCELLED
2020-06-26 18:59:20.308 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 18:59:20.308 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 25 01 FF 25 DB D3
2020-06-26 18:59:20.317 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack.
2020-06-26 18:59:20.318 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 868: Transaction not completed
2020-06-26 18:59:25.317 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 19: TID 868: Timeout at state WAIT_REQUEST. 3 retries remaining.
2020-06-26 18:59:36.144 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 219, Status = Transmission complete, no ACK received(1)
2020-06-26 18:59:36.145 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 18:59:36.145 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: CANCEL while sending message. Requeueing - 2 attempts left!
2020-06-26 18:59:36.145 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2020-06-26 18:59:36.145 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Added 868 to queue - size 1
2020-06-26 18:59:36.146 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 25 01 FF 25 DC D4
2020-06-26 18:59:36.146 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 868: Transaction not completed
2020-06-26 18:59:36.155 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack.
2020-06-26 18:59:36.155 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 868: Transaction not completed
2020-06-26 18:59:41.155 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 19: TID 868: Timeout at state WAIT_REQUEST. 2 retries remaining.
2020-06-26 18:59:52.013 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 220, Status = Transmission complete, no ACK received(1)
2020-06-26 18:59:52.013 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 18:59:52.014 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: CANCEL while sending message. Requeueing - 1 attempts left!
2020-06-26 18:59:52.014 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue
2020-06-26 18:59:52.014 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Added 868 to queue - size 1
2020-06-26 18:59:52.014 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 25 01 FF 25 DD D5
2020-06-26 18:59:52.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 868: Transaction not completed
2020-06-26 18:59:52.023 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack.
2020-06-26 18:59:52.023 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 868: Transaction not completed
2020-06-26 18:59:57.023 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 19: TID 868: Timeout at state WAIT_REQUEST. 1 retries remaining.
2020-06-26 19:00:07.801 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 221, Status = Transmission complete, no ACK received(1)
2020-06-26 19:00:07.802 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 19:00:07.802 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Retry count exceeded. Discarding message: TID 868: [CANCELLED] priority=Set, requiresResponse=true, callback: 221
2020-06-26 19:00:07.802 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: TID 868: Transaction completed
2020-06-26 19:00:07.802 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: notifyTransactionResponse TID:868 CANCELLED
2020-06-26 19:00:07.803 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-26 19:01:43.264 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (DEAD:DELETE_SUC_ROUTES)
2020-06-26 19:01:43.264 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2020-06-26 19:01:43.264 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Setting ONLINE
2020-06-26 19:01:43.265 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 19: Node Status event - Node is ALIVE
2020-06-26 19:01:43.265 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: Node is ALIVE. Init stage is DELETE_SUC_ROUTES.
2020-06-26 19:01:43.266 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2020-06-26 19:01:43.266 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Setting ONLINE
2020-06-26 19:01:43.266 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 19: Node Status event - Node is ALIVE
2020-06-26 19:01:43.266 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-06-26 19:01:43.266 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY not supported
2020-06-26 19:01:43.266 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 19: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-06-26 19:01:43.266 [DEBUG] [ernal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 19: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2020-06-26 19:01:43.267 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-06-26 19:01:43.267 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0E+1
2020-06-26 19:01:43.267 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Updating channel state zwave:device:a5365e91:node19:meter_watts to 0 [DecimalType]
2020-06-26 19:01:43.267 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Commands processed 1.
2020-06-26 19:01:43.268 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3b9d398a.
2020-06-26 19:01:59.057 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DELETE_SUC_ROUTES)
2020-06-26 19:01:59.057 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: Incoming command class COMMAND_CLASS_HAIL, endpoint 0
2020-06-26 19:01:59.057 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY not supported
2020-06-26 19:01:59.057 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 19: Received COMMAND_CLASS_HAIL V1 HAIL
2020-06-26 19:01:59.057 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Commands processed 1.

so what i tend to see is that the device will send a meter report, openhad will class it as awake, until you try and send something to it, where it will go offline again.

it doesnt seem to complete the command

I’m getting power reports from it now. but i had to manually turn it on. but nothing i send to it via opehab seems to get there.

    2020-06-26 21:38:03.296 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-06-26 21:38:05.862 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 13 0A 32 02 21 74 00 00 0C 13 00 00 88
2020-06-26 21:38:05.863 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=19, callback=0, payload=00 13 0A 32 02 21 74 00 00 0C 13 00 00
2020-06-26 21:38:05.863 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=19, callback=0, payload=00 13 0A 32 02 21 74 00 00 0C 13 00 00
2020-06-26 21:38:05.863 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-06-26 21:38:05.863 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DELETE_SUC_ROUTES)
2020-06-26 21:38:05.863 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-06-26 21:38:05.864 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY not supported
2020-06-26 21:38:05.864 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 19: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-06-26 21:38:05.864 [DEBUG] [ernal.protocol.commandclass.ZWaveMeterCommandClass] - NODE 19: Meter: Type=Electric(1), Scale=W(2), Value=3.091
2020-06-26 21:38:05.864 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-06-26 21:38:05.864 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=3.091
2020-06-26 21:38:05.864 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 19: Updating channel state zwave:device:a5365e91:node19:meter_watts to 3.091 [DecimalType]
2020-06-26 21:38:05.864 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Commands processed 1.
2020-06-26 21:38:05.864 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@24ecd54a.
2020-06-26 21:38:05.865 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-06-26 21:38:05.865 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-06-26 21:38:05.865 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-26 21:38:05.865 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-06-26 21:38:06.977 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 08 02 82 01 7A
2020-06-26 21:38:06.978 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 02 82 01

@chris what do you think?

From a quick look, it seems that the device is not responding - I see requests timing out and it looks like the device didn’t respond (which is normally what the timeout means).

Does the crow have to fly through walls?

8 meters is possibly getting a bit far potentially - it really depends on a lot of things - how many walls are in the way, what the walls are made of, what the devices are etc.

But isn’t that when it should run through other devices? It seems to think it can hit the controller directly. And noThing I do with placing smart switches within a few meters changes its routing.

This is an aeotec nano. Yes there are walls and even a floor between these controller and switch

Maybe - I have no information about your network. How many devices there are, if they are mains, where they are located etc so I’m just offering ideas.

Probably this is correct since routing is generally pretty static, however you probably can’t actually tell this
since there is nothing to tell you the routing (or maybe you have a sniffer?).

What are they made of?

I think 16 devices. All mains.

All mostly at the controller end of the house, I have started putting devices at the out reaches.

No sniffer just the si labs pc controller. Can that tell me routing? I know it can set routes, but the doco is a little sparse on how to do this, and what it should look like.

Not brick, Just timber, dry wall ( I think that’s what you call gib board in the us)

I’d posted this similar topic with a node made and floor plan: Zwave node - weird neighbours

Node 19 is on the 2nd floor, Probably close to the node 7 which is in the little room at the bottom of the floor plan.

Generally the zwave has been good, but adding this last node has caused me no end of problems. It was generally working, and responding, but has since stopped.

So things kind of stablised. But there were a couple of nodes that would never move off ping or request_nif. So I let it do a heal over night. Most have come back, one was being annoying, so I’ve moved it 1m and it’s now got a signal. But again I’m left with a couple of devices that seem to work, but they are not completing their initialisation.

2020-07-07 07:44:15.639 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 8: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:19.478 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:20.791 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 13: Application Command Request (ALIVE:UPDATE_NEIGHBORS)
2020-07-07 07:44:33.253 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DELETE_SUC_ROUTES)
2020-07-07 07:44:33.629 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DELETE_SUC_ROUTES)
2020-07-07 07:44:33.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DELETE_SUC_ROUTES)
2020-07-07 07:44:34.076 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DELETE_SUC_ROUTES)
2020-07-07 07:44:34.545 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 19: Application Command Request (ALIVE:DELETE_SUC_ROUTES)
2020-07-07 07:44:35.473 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:38.312 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:38.385 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:40.553 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 8: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:41.409 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:47.478 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:47.909 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:48.110 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2020-07-07 07:44:50.789 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 13: Application Command Request (ALIVE:UPDATE_NEIGHBORS)

These did a heal at 3am, and it’s currently 7am. I know form previous experience, that these will never resolve. Is there anything I can do to help them along? Does sending commands to these devices (on, off, on, off) help it carry on the process?
@chris

Sometimes deleting a Thing from OH (NOT excluding from the network) and then rediscovering, keeping it awake helps.

I’ve never had good luck removing and re-adding a device…