Z-Wave devices all dead

Cougar281 · May 26, 2018, 11:22pm

I’ve been working on some automation for my sisters house, and currently have three z-wave switches set up, which have been working fine since I moved my HA RPi as close to the center between all three switches as I could get. Once of them is maybe 10’ away, line of sight, the other two are on the next level up, maybe 15-20’ away from the HA RPi. I’m using a Z-Way Razberry for Zwave and like I said, they have been fine and being reachable without issue. Today, I swapped out SD cards because for whatever reason, the build I had been running was a little flaky. It wasn’t able to set up envisalink, logbook or history for some reason, but the Z-wave had been working fine. After swapping out the card, it booted up and all three switches came up as ready and everything was happy. So I go home and work on adjusting the automations and names and that’s when everything went sideways. Although the rename of the nodes seemed to work far better than last time I tried it (I don’t recall what version that was, but it’s 69.1 now), it seems like everything went sideways after I did the rename.

The initialization of nodes seems completely hit or miss. Right now, it seems like ‘node 4’, which is one of the upstairs nodes, is alive, but the other two, including the one that is line of sight, are dead.

Anyone have any thoughts? I know the current setup isn’t optimal, but it went from working to not working with NO physical changes - locations of everything are unchanged. I even went so far as to turn off the Wireless AP that, best I can tell, as odd as it seems, given one is ~400Mhz and the other is 5Ghz, with the 5Ghz radio enabled, it completely clobbered the Z-Wave network (as soon as I disabled 5Ghz, Z-wave popped right back up). The real kicker is that the one that there is NO WAY it can’t contact is listed as dead… The two upstairs ones, I could see potentially being hit or miss, but there’s no reason the one that is 10’ or less line of sight would be dead. and it all seemed to go sideways after I renamed nodes.

firstof9 · May 27, 2018, 12:28am

Post the OZW_Log.txt

Cougar281 · May 27, 2018, 1:40am

This should have one reboot where everything came up dead, and a subsequent reboot where one node came up alive.

2018-05-26 20:33:56.698 Always, OpenZwave Version 1.4.2926 Starting Up
2018-05-26 20:33:58.635 Info, Setting Up Provided Network Key for Secure Communications
2018-05-26 20:33:58.642 Info, mgr,     Added driver for controller /dev/ttyS0
2018-05-26 20:33:58.642 Info,   Opening controller /dev/ttyS0
2018-05-26 20:33:58.642 Info, Trying to open serial port /dev/ttyS0 (attempt 1)
2018-05-26 20:33:58.642 Info, Serial port /dev/ttyS0 opened (attempt 1)
2018-05-26 20:33:58.643 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-05-26 20:33:58.643 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-05-26 20:33:58.643 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-05-26 20:33:58.643 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-05-26 20:33:58.643 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-05-26 20:33:58.643 Detail, 
2018-05-26 20:33:58.643 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-05-26 20:33:58.646 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x30, 0x35, 0x00, 0x01, 0x97
2018-05-26 20:33:58.646 Detail, 
2018-05-26 20:33:58.646 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2018-05-26 20:33:58.646 Info, contrlr,     Static Controller library, version Z-Wave 4.05
2018-05-26 20:33:58.646 Detail, Node045,   Expected reply was received
2018-05-26 20:33:58.646 Detail, Node045,   Message transaction complete
2018-05-26 20:33:58.646 Detail, 
2018-05-26 20:33:58.646 Detail, contrlr, Removing current message
2018-05-26 20:33:58.646 Detail, 
2018-05-26 20:33:58.647 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-05-26 20:33:58.649 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xcf, 0x1a, 0x77, 0x16, 0x01, 0x63
2018-05-26 20:33:58.649 Detail, 
2018-05-26 20:33:58.649 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xcf1a7716.  Our node ID = 1
2018-05-26 20:33:58.649 Detail, Node026,   Expected reply was received
2018-05-26 20:33:58.649 Detail, Node026,   Message transaction complete
2018-05-26 20:33:58.649 Detail, 
2018-05-26 20:33:58.649 Detail, contrlr, Removing current message
2018-05-26 20:33:58.649 Detail, 
2018-05-26 20:33:58.649 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-05-26 20:33:58.650 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x08, 0xf7
2018-05-26 20:33:58.650 Detail, 
2018-05-26 20:33:58.651 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2018-05-26 20:33:58.651 Info, contrlr,     There is no SUC ID Server (SIS) in this network.
2018-05-26 20:33:58.651 Info, contrlr,     The PC controller is a primary controller.
2018-05-26 20:33:58.651 Detail, Node247,   Expected reply was received
2018-05-26 20:33:58.651 Detail, Node247,   Message transaction complete
2018-05-26 20:33:58.651 Detail, 
2018-05-26 20:33:58.651 Detail, contrlr, Removing current message
2018-05-26 20:33:58.651 Detail, 
2018-05-26 20:33:58.651 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-05-26 20:33:58.656 Detail, contrlr,   Received: 0x01, 0x2b, 0x01, 0x07, 0x05, 0x04, 0x01, 0x47, 0x04, 0x00, 0x00, 0x02, 0xfe, 0x83, 0xff, 0x88, 0xcf, 0x1f, 0x00, 0x00, 0xfb, 0x9f, 0x7d, 0xa0, 0x67, 0x00, 0x80, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xe8, 0x73, 0x00, 0x00, 0x0e, 0x00, 0x00, 0x40, 0x1a, 0x00, 0x5e
2018-05-26 20:33:58.656 Detail, 
2018-05-26 20:33:58.656 Info, contrlr,  Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2018-05-26 20:33:58.656 Info, contrlr,     Serial API Version:   5.4
2018-05-26 20:33:58.656 Info, contrlr,     Manufacturer ID:      0x0147
2018-05-26 20:33:58.656 Info, contrlr,     Product Type:         0x0400
2018-05-26 20:33:58.657 Info, contrlr,     Product ID:           0x0002
2018-05-26 20:33:58.657 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2018-05-26 20:33:58.657 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2018-05-26 20:33:58.657 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2018-05-26 20:33:58.657 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2018-05-26 20:33:58.657 Detail, Node004,   Expected reply was received
2018-05-26 20:33:58.657 Detail, Node004,   Message transaction complete
2018-05-26 20:33:58.657 Detail, 
2018-05-26 20:33:58.657 Detail, contrlr, Removing current message
2018-05-26 20:33:58.657 Detail, 
2018-05-26 20:33:58.657 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-05-26 20:33:58.659 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2018-05-26 20:33:58.659 Detail, 
2018-05-26 20:33:58.659 Info, contrlr, Received reply to GET_SUC_NODE_ID.  Node ID = 0
2018-05-26 20:33:58.659 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node
2018-05-26 20:33:58.659 Detail, Node172,   Expected reply was received
2018-05-26 20:33:58.659 Detail, Node172,   Message transaction complete
2018-05-26 20:33:58.659 Detail, 
2018-05-26 20:33:58.659 Detail, contrlr, Removing current message
2018-05-26 20:33:58.659 Detail, 
2018-05-26 20:33:58.659 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2018-05-26 20:33:58.712 Detail, contrlr,   Received: 0x01, 0x25, 0x01, 0x1c, 0x01, 0x20, 0x9f, 0x0d, 0x3d, 0x08, 0xc4, 0xc6, 0x45, 0x50, 0x3e, 0x90, 0x87, 0xee, 0x6a, 0xce, 0xcc, 0x18, 0x1e, 0x70, 0xab, 0xa8, 0xd2, 0xae, 0x23, 0x60, 0xa9, 0xef, 0x06, 0xa1, 0x16, 0xa3, 0x9d, 0x7a, 0x00
2018-05-26 20:33:58.712 Detail, 
2018-05-26 20:33:58.712 Info, contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2018-05-26 20:33:58.712 Detail, Node032,   Expected reply was received
2018-05-26 20:33:58.712 Detail, Node032,   Message transaction complete
2018-05-26 20:33:58.712 Detail, 
2018-05-26 20:33:58.712 Detail, contrlr, Removing current message
2018-05-26 20:33:58.713 Detail, 
2018-05-26 20:33:58.713 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x02) - FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2018-05-26 20:33:58.772 Detail, contrlr,   Received: 0x01, 0x25, 0x01, 0x02, 0x05, 0x00, 0x1d, 0x39, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x05, 0x00, 0xfd
2018-05-26 20:33:58.772 Detail, 
2018-05-26 20:33:58.772 Info, mgr,     Driver with Home ID of 0xcf1a7716 is now ready.
2018-05-26 20:33:58.772 Info, 
2018-05-26 20:33:58.791 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2018-05-26 20:33:58.791 Info, contrlr,     Node 001 - Known
2018-05-26 20:33:58.791 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-26 20:33:58.791 Detail, Node001, QueryStage_CacheLoad
2018-05-26 20:33:58.791 Info, Node001, Node Identity Codes: 0147:0400:0002
2018-05-26 20:33:58.791 Detail, Node001, QueryStage_Associations
2018-05-26 20:33:58.791 Detail, Node001, QueryStage_Neighbors
2018-05-26 20:33:58.791 Detail, contrlr, Requesting routing info (neighbor list) for Node 1
2018-05-26 20:33:58.792 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2018-05-26 20:33:58.792 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2018-05-26 20:33:58.792 Info, contrlr,     Node 004 - Known
2018-05-26 20:33:58.792 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-26 20:33:58.792 Detail, Node004, QueryStage_CacheLoad
2018-05-26 20:33:58.792 Info, Node004, Node Identity Codes: 0000:0000:0000
2018-05-26 20:33:58.792 Info, Node004, NoOperation::Set - Routing=true
2018-05-26 20:33:58.792 Detail, Node004, Queuing (NoOp) NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xcc
2018-05-26 20:33:58.792 Detail, Node004, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-26 20:33:58.792 Info, contrlr,     Node 005 - Known
2018-05-26 20:33:58.792 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-26 20:33:58.792 Detail, Node005, QueryStage_CacheLoad
2018-05-26 20:33:58.792 Info, Node005, Node Identity Codes: 0000:0000:0000
2018-05-26 20:33:58.792 Info, Node005, NoOperation::Set - Routing=true
2018-05-26 20:33:58.792 Detail, Node005, Queuing (NoOp) NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x0b, 0xcc
2018-05-26 20:33:58.792 Detail, Node005, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-26 20:33:58.792 Info, contrlr,     Node 006 - Known
2018-05-26 20:33:58.792 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-26 20:33:58.792 Detail, Node006, QueryStage_CacheLoad
2018-05-26 20:33:58.792 Info, Node006, Node Identity Codes: 001d:0602:0334
2018-05-26 20:33:58.792 Info, Node006, NoOperation::Set - Routing=true
2018-05-26 20:33:58.792 Detail, Node006, Queuing (NoOp) NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xc8
2018-05-26 20:33:58.793 Detail, Node006, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-26 20:33:58.793 Detail,   Expected reply was received
2018-05-26 20:33:58.793 Detail,   Message transaction complete
2018-05-26 20:33:58.793 Detail, 
2018-05-26 20:33:58.793 Detail, contrlr, Removing current message
2018-05-26 20:33:58.793 Detail, Node001, Notification: DriverReady
-SNIP-
2018-05-26 20:33:58.963 Detail, Node006, Notification: ValueAdded
2018-05-26 20:33:58.967 Detail, Node006, Notification: NodeNaming
2018-05-26 20:33:58.969 Detail, 
2018-05-26 20:33:58.969 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x06) - FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2018-05-26 20:33:58.970 Detail, contrlr,   Received: 0x01, 0x05, 0x01, 0x06, 0x64, 0x0f, 0x96
2018-05-26 20:33:58.971 Detail, 
2018-05-26 20:33:58.971 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_SET_TIMEOUTS
2018-05-26 20:33:58.971 Detail, Node015,   Expected reply was received
2018-05-26 20:33:58.971 Detail, Node015,   Message transaction complete
2018-05-26 20:33:58.971 Detail, 
2018-05-26 20:33:58.971 Detail, contrlr, Removing current message
2018-05-26 20:33:58.971 Detail, 
2018-05-26 20:33:58.971 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x00) - FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2018-05-26 20:33:58.972 Detail, contrlr, Removing current message
2018-05-26 20:33:58.972 Detail, 
2018-05-26 20:33:58.972 Info, Node001, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2018-05-26 20:33:58.977 Detail, Node001,   Received: 0x01, 0x20, 0x01, 0x80, 0x20, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x7e
2018-05-26 20:33:58.977 Detail, 
2018-05-26 20:33:58.977 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-05-26 20:33:58.977 Info, Node001,     Neighbors of this node are:
2018-05-26 20:33:58.977 Info, Node001,     Node 6
2018-05-26 20:33:58.977 Detail,   Expected reply was received
2018-05-26 20:33:58.977 Detail,   Message transaction complete
2018-05-26 20:33:58.977 Detail, 
2018-05-26 20:33:58.977 Detail, Node001, Removing current message
2018-05-26 20:33:58.978 Detail, 
2018-05-26 20:33:58.978 Info, Node004, Sending (NoOp) message (Callback ID=0x0a, Expected Reply=0x13) - NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xcc
2018-05-26 20:33:59.042 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:33:59.042 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:10.133 Error, Node004, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-05-26 20:34:10.133 Detail, Node004, Removing current message
2018-05-26 20:34:10.133 Detail, Node004, Notification: Notification - TimeOut
2018-05-26 20:34:10.144 Detail, 
2018-05-26 20:34:10.144 Info, Node005, Sending (NoOp) message (Callback ID=0x0b, Expected Reply=0x13) - NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x0b, 0xcc
2018-05-26 20:34:10.209 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:10.209 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:10.215 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x0b, 0x01, 0x00, 0x07, 0xe6
2018-05-26 20:34:10.215 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x0b received (expected 0x0b)
2018-05-26 20:34:10.215 Info, Node005, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:10.215 Warning, Node005, WARNING: Device is not a sleeping node.
2018-05-26 20:34:10.215 Info, Node005, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 0 pending 1
2018-05-26 20:34:10.215 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:10.215 Detail, Node001,   Expected reply was received
2018-05-26 20:34:10.215 Detail, Node001,   Message transaction complete
2018-05-26 20:34:10.215 Detail, 
2018-05-26 20:34:10.215 Detail, Node005, Removing current message
2018-05-26 20:34:10.215 Detail, Node005, Notification: Notification - NoOperation
2018-05-26 20:34:10.217 Detail, 
2018-05-26 20:34:10.217 Info, Node006, Sending (NoOp) message (Callback ID=0x0c, Expected Reply=0x13) - NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xc8
2018-05-26 20:34:10.224 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:10.224 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:14.573 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x0c, 0x01, 0x01, 0xb3, 0x54
2018-05-26 20:34:14.573 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x0c received (expected 0x0c)
2018-05-26 20:34:14.573 Info, Node006, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:14.574 Warning, Node006, WARNING: Device is not a sleeping node.
2018-05-26 20:34:14.574 Info, Node006, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 0 pending 1
2018-05-26 20:34:14.574 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:14.574 Detail, Node001,   Expected reply was received
2018-05-26 20:34:14.574 Detail, Node001,   Message transaction complete
2018-05-26 20:34:14.574 Detail, 
2018-05-26 20:34:14.574 Detail, Node006, Removing current message
2018-05-26 20:34:14.574 Detail, Node006, Notification: Notification - NoOperation
2018-05-26 20:34:14.577 Detail, Node001, Query Stage Complete (Neighbors)
2018-05-26 20:34:14.577 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2018-05-26 20:34:14.577 Detail, Node001, QueryStage_Session
2018-05-26 20:34:14.577 Detail, Node001, QueryStage_Dynamic
2018-05-26 20:34:14.577 Detail, Node001, QueryStage_Configuration
2018-05-26 20:34:14.577 Detail, Node001, QueryStage_Complete
2018-05-26 20:34:14.578 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-26 20:34:14.578 Warning, CheckCompletedNodeQueries all=0, deadFound=0 sleepingOnly=0
2018-05-26 20:34:14.578 Detail, Node001, Notification: NodeQueriesComplete
2018-05-26 20:34:14.580 Detail, Node004, Query Stage Complete (CacheLoad)
2018-05-26 20:34:14.580 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Associations live=1
2018-05-26 20:34:14.581 Detail, Node004, QueryStage_Associations
2018-05-26 20:34:14.581 Detail, Node004, QueryStage_Neighbors
2018-05-26 20:34:14.581 Detail, Requesting routing info (neighbor list) for Node 4
2018-05-26 20:34:14.581 Detail, Node004, Queuing (Command) Get Routing Info (Node=4): 0x01, 0x07, 0x00, 0x80, 0x04, 0x00, 0x00, 0x03, 0x7f
2018-05-26 20:34:14.581 Detail, Node004, Queuing (Query) Query Stage Complete (Neighbors)
2018-05-26 20:34:14.581 Detail, 
2018-05-26 20:34:14.581 Info, Node004, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=4): 0x01, 0x07, 0x00, 0x80, 0x04, 0x00, 0x00, 0x03, 0x7f
2018-05-26 20:34:14.586 Detail, Node004,   Received: 0x01, 0x20, 0x01, 0x80, 0x30, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x6e
2018-05-26 20:34:14.586 Detail, 
2018-05-26 20:34:14.587 Info, Node004, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-05-26 20:34:14.587 Info, Node004,     Neighbors of this node are:
2018-05-26 20:34:14.587 Info, Node004,     Node 5
2018-05-26 20:34:14.587 Info, Node004,     Node 6
2018-05-26 20:34:14.587 Detail,   Expected reply was received
2018-05-26 20:34:14.587 Detail,   Message transaction complete
2018-05-26 20:34:14.587 Detail, 
2018-05-26 20:34:14.587 Detail, Node004, Removing current message
2018-05-26 20:34:14.587 Detail, Node005, Query Stage Complete (CacheLoad)
2018-05-26 20:34:14.587 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=1 queryStage=CacheLoad live=1
2018-05-26 20:34:14.587 Detail, Node005, QueryStage_CacheLoad
2018-05-26 20:34:14.587 Info, Node005, Node Identity Codes: 0000:0000:0000
2018-05-26 20:34:14.588 Info, Node005, NoOperation::Set - Routing=true
2018-05-26 20:34:14.588 Detail, Node005, Queuing (NoOp) NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x0d, 0xca
2018-05-26 20:34:14.588 Detail, Node005, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-26 20:34:14.588 Detail, 
2018-05-26 20:34:14.588 Info, Node005, Sending (NoOp) message (Callback ID=0x0d, Expected Reply=0x13) - NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x0d, 0xca
2018-05-26 20:34:14.653 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:14.653 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:14.888 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x01, 0x00, 0x1e, 0xf9
2018-05-26 20:34:14.888 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d)
2018-05-26 20:34:14.888 Info, Node005, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:14.888 Warning, Node005, WARNING: Device is not a sleeping node.
2018-05-26 20:34:14.888 Info, Node005, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 1 pending 1
2018-05-26 20:34:14.888 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:14.888 Detail, Node001,   Expected reply was received
2018-05-26 20:34:14.889 Detail, Node001,   Message transaction complete
2018-05-26 20:34:14.889 Detail, 
2018-05-26 20:34:14.889 Detail, Node005, Removing current message
2018-05-26 20:34:14.889 Detail, Node005, Notification: Notification - NoOperation
2018-05-26 20:34:14.892 Detail, Node006, Query Stage Complete (CacheLoad)
2018-05-26 20:34:14.892 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=1 queryStage=CacheLoad live=1
2018-05-26 20:34:14.892 Detail, Node006, QueryStage_CacheLoad
2018-05-26 20:34:14.892 Info, Node006, Node Identity Codes: 001d:0602:0334
2018-05-26 20:34:14.892 Info, Node006, NoOperation::Set - Routing=true
2018-05-26 20:34:14.892 Detail, Node006, Queuing (NoOp) NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0e, 0xca
2018-05-26 20:34:14.892 Detail, Node006, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-26 20:34:14.892 Detail, 
2018-05-26 20:34:14.892 Info, Node006, Sending (NoOp) message (Callback ID=0x0e, Expected Reply=0x13) - NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0e, 0xca
2018-05-26 20:34:14.900 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:14.900 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:18.971 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x0e, 0x01, 0x01, 0x98, 0x7d
2018-05-26 20:34:18.971 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x0e received (expected 0x0e)
2018-05-26 20:34:18.971 Info, Node006, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:18.972 Warning, Node006, WARNING: Device is not a sleeping node.
2018-05-26 20:34:18.972 Info, Node006, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 1 pending 1
2018-05-26 20:34:18.972 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:18.972 Detail, Node001,   Expected reply was received
2018-05-26 20:34:18.972 Detail, Node001,   Message transaction complete
2018-05-26 20:34:18.972 Detail, 
2018-05-26 20:34:18.972 Detail, Node006, Removing current message
2018-05-26 20:34:18.972 Detail, Node006, Notification: Notification - NoOperation
2018-05-26 20:34:18.975 Detail, Node004, Query Stage Complete (Neighbors)
2018-05-26 20:34:18.975 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2018-05-26 20:34:18.975 Detail, Node004, QueryStage_Session
2018-05-26 20:34:18.976 Detail, Node004, Queuing (Query) SwitchAllCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x27, 0x02, 0x25, 0x0f, 0xec
2018-05-26 20:34:18.976 Detail, Node004, Queuing (Query) Query Stage Complete (Session)
2018-05-26 20:34:18.976 Detail, Node005, Query Stage Complete (CacheLoad)
2018-05-26 20:34:18.976 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=2 queryStage=CacheLoad live=1
2018-05-26 20:34:18.976 Detail, Node005, QueryStage_CacheLoad
2018-05-26 20:34:18.976 Info, Node005, Node Identity Codes: 0000:0000:0000
2018-05-26 20:34:18.976 Info, Node005, NoOperation::Set - Routing=true
2018-05-26 20:34:18.976 Detail, Node005, Queuing (NoOp) NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x10, 0xd7
2018-05-26 20:34:18.976 Detail, Node005, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-26 20:34:18.977 Detail, 
2018-05-26 20:34:18.977 Info, Node005, Sending (NoOp) message (Callback ID=0x10, Expected Reply=0x13) - NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x10, 0xd7
2018-05-26 20:34:19.041 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:19.042 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:19.276 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x10, 0x01, 0x00, 0x1d, 0xe7
2018-05-26 20:34:19.277 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x10 received (expected 0x10)
2018-05-26 20:34:19.277 Info, Node005, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:19.277 Warning, Node005, WARNING: Device is not a sleeping node.
2018-05-26 20:34:19.277 Error, Node005, ERROR: node presumed dead
2018-05-26 20:34:19.277 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-26 20:34:19.277 Warning, CheckCompletedNodeQueries all=0, deadFound=1 sleepingOnly=0
2018-05-26 20:34:19.277 Info, Node005, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 2 pending 1
2018-05-26 20:34:19.277 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:19.277 Detail, Node001,   Expected reply was received
2018-05-26 20:34:19.277 Detail, Node001,   Message transaction complete
2018-05-26 20:34:19.277 Detail, 
2018-05-26 20:34:19.278 Detail, Node005, Removing current message
2018-05-26 20:34:19.278 Detail, Node005, Notification: Notification - NoOperation
2018-05-26 20:34:19.280 Detail, Node005, Notification: Notification - Node Dead
2018-05-26 20:34:19.283 Detail, Node006, Query Stage Complete (CacheLoad)
2018-05-26 20:34:19.283 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=2 queryStage=CacheLoad live=1
2018-05-26 20:34:19.283 Detail, Node006, QueryStage_CacheLoad
2018-05-26 20:34:19.283 Info, Node006, Node Identity Codes: 001d:0602:0334
2018-05-26 20:34:19.283 Info, Node006, NoOperation::Set - Routing=true
2018-05-26 20:34:19.283 Detail, Node006, Queuing (NoOp) NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x11, 0xd5
2018-05-26 20:34:19.283 Detail, Node006, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-26 20:34:19.283 Detail, 
2018-05-26 20:34:19.283 Info, Node006, Sending (NoOp) message (Callback ID=0x11, Expected Reply=0x13) - NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x11, 0xd5
2018-05-26 20:34:19.291 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:19.291 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:23.361 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x11, 0x01, 0x01, 0x98, 0x62
2018-05-26 20:34:23.361 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x11 received (expected 0x11)
2018-05-26 20:34:23.362 Info, Node006, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:23.362 Warning, Node006, WARNING: Device is not a sleeping node.
2018-05-26 20:34:23.362 Error, Node006, ERROR: node presumed dead
2018-05-26 20:34:23.362 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-26 20:34:23.362 Warning, CheckCompletedNodeQueries all=0, deadFound=1 sleepingOnly=0
2018-05-26 20:34:23.362 Info, Node006, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 2 pending 1
2018-05-26 20:34:23.362 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:23.362 Detail, Node001,   Expected reply was received
2018-05-26 20:34:23.362 Detail, Node001,   Message transaction complete
2018-05-26 20:34:23.362 Detail, 
2018-05-26 20:34:23.362 Detail, Node006, Removing current message
2018-05-26 20:34:23.363 Detail, Node006, Notification: Notification - NoOperation
2018-05-26 20:34:23.366 Detail, Node006, Notification: Notification - Node Dead
2018-05-26 20:34:23.369 Detail, 
2018-05-26 20:34:23.369 Info, Node004, Sending (Query) message (Callback ID=0x0f, Expected Reply=0x04) - SwitchAllCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x27, 0x02, 0x25, 0x0f, 0xec
2018-05-26 20:34:23.434 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:23.434 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:23.684 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x0f, 0x01, 0x00, 0x1f, 0xfa
2018-05-26 20:34:23.684 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x0f received (expected 0x0f)
2018-05-26 20:34:23.684 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:23.684 Warning, Node004, WARNING: Device is not a sleeping node.
2018-05-26 20:34:23.684 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:27.783 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x0f, 0x01, 0x01, 0xb9, 0x5d
2018-05-26 20:34:27.784 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x0f received (expected 0x00)
2018-05-26 20:34:27.784 Warning, Node004, WARNING: Unexpected Callback ID received
2018-05-26 20:34:33.370 Error, Node004, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-05-26 20:34:33.370 Detail, Node004, Removing current message
2018-05-26 20:34:33.370 Detail, Node004, Notification: Notification - TimeOut
2018-05-26 20:34:33.373 Detail, Node004, Query Stage Complete (Session)
2018-05-26 20:34:33.373 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2018-05-26 20:34:33.373 Detail, Node004, QueryStage_Dynamic
2018-05-26 20:34:33.373 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x12, 0xf0
2018-05-26 20:34:33.373 Detail, Node004, Queuing (Query) Query Stage Complete (Dynamic)
2018-05-26 20:34:33.374 Detail, 
2018-05-26 20:34:33.374 Info, Node004, Sending (Send) message (Callback ID=0x12, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x12, 0xf0
2018-05-26 20:34:33.439 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-26 20:34:33.439 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-26 20:34:37.817 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x12, 0x01, 0x01, 0xbc, 0x45
2018-05-26 20:34:37.818 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x12 received (expected 0x12)
2018-05-26 20:34:37.818 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-26 20:34:37.818 Warning, Node004, WARNING: Device is not a sleeping node.
2018-05-26 20:34:37.818 Detail, Node001,   Expected callbackId was received
2018-05-26 20:34:43.375 Error, Node004, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-05-26 20:34:43.375 Detail, Node004, Removing current message
2018-05-26 20:34:43.376 Detail, Node004, Notification: Notification - TimeOut
2018-05-26 20:34:43.378 Detail, Node005, Query Stage Complete (CacheLoad)
2018-05-26 20:34:43.378 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=0
2018-05-26 20:34:43.379 Detail, Node006, Query Stage Complete (CacheLoad)
2018-05-26 20:34:43.379 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=0
2018-05-26 20:34:43.379 Detail, Node004, Query Stage Complete (Dynamic)
2018-05-26 20:34:43.379 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2018-05-26 20:34:43.379 Detail, Node004, QueryStage_Configuration
2018-05-26 20:34:43.379 Detail, Node004, QueryStage_Complete
2018-05-26 20:34:43.379 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-26 20:34:43.379 Warning, CheckCompletedNodeQueries all=1, deadFound=1 sleepingOnly=1
2018-05-26 20:34:43.379 Info,          Node query processing complete except for dead nodes.
2018-05-26 20:34:43.379 Detail, Node004, Notification: NodeQueriesComplete
2018-05-26 20:34:43.382 Detail, contrlr, Notification: AllNodesQueriedSomeDead

firstof9 · May 27, 2018, 1:53am

Based on the log, the devices are no longer responding to the controller. Have you tried a heal?

Cougar281 · May 27, 2018, 2:03am

Yes, I did try that once… The blurbs I saw seemed to indicate that the nodes were ‘presumed dead’, so they were totally ignored.

Like I said, what’s REALLY getting me here is the fact that the controller hasn’t moved, and everything was working fine until I tried to rename nodes. Along with the one switch that there is NO WAY is out of range (The upstairs ones, even though they are not crazy far away, I could see maybe being hit or miss).

I’ve got two plug in nodes that I’m not using that I could clear and add to that controller, but if it seems to think that the one that is line of sight is dead…

2018-05-26 20:59:10.427 Warning, WARNING: REQUEST_NEIGHBOR_UPDATE_FAILED
2018-05-26 20:59:10.427 Detail, Notification: ControllerCommand - Failed
2018-05-26 20:59:10.428 Info, Requesting Neighbor Update for node 4
2018-05-26 20:59:10.428 Detail, Node004, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=4): 0x01, 0x05, 0x00, 0x48, 0x04, 0x14, 0xa2
2018-05-26 20:59:10.428 Detail, Notification: ControllerCommand - Starting
2018-05-26 20:59:10.429 Error, Node004, ERROR: Dropping command because node is presumed dead
2018-05-26 20:59:10.429 Detail, Node004, Removing current message
2018-05-26 20:59:10.429 Detail, Notification: ControllerCommand - Error - Failed
2018-05-26 20:59:10.429 Info, Requesting Neighbor Update for node 5
2018-05-26 20:59:10.429 Detail, Node005, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=5): 0x01, 0x05, 0x00, 0x48, 0x05, 0x15, 0xa2
2018-05-26 20:59:10.430 Detail, Notification: ControllerCommand - Starting
2018-05-26 20:59:10.430 Error, Node005, ERROR: Dropping command because node is presumed dead
2018-05-26 20:59:10.430 Detail, Node005, Removing current message
2018-05-26 20:59:10.430 Detail, Notification: ControllerCommand - Error - Failed
2018-05-26 20:59:10.431 Info, Requesting Neighbor Update for node 6
2018-05-26 20:59:10.431 Detail, Node006, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=6): 0x01, 0x05, 0x00, 0x48, 0x06, 0x16, 0xa2
2018-05-26 20:59:10.431 Detail, Notification: ControllerCommand - Starting
2018-05-26 20:59:10.432 Error, Node006, ERROR: Dropping command because node is presumed dead
2018-05-26 20:59:10.432 Detail, Node006, Removing current message
2018-05-26 20:59:10.432 Detail, Notification: ControllerCommand - Error - Failed

anon43302295 · May 27, 2018, 2:15am

I’m having similar problems.

Cougar281 · May 27, 2018, 2:33am

I’m going to make a trip back out there, maybe tomorrow, to swap cards and see what happens with the previous instance… If I boot that and everything’s A-OK, then… but on the other hand, I have the sane Z-Way controller, with the same build, in my house, and it’s working fine (so far… but I haven’t tried to rename anything).

Cougar281 · May 27, 2018, 5:13am

To add some more… What I’ve found is while my issues don’t follow mf_social’s exactly (stopping and starting the Z-Wave network only results in duplicate ‘dead’ devices), when I reboot it, sometimes a device will show up as ‘ok’, and when I activate the scene to turn it on or off (whichever state it’s not in), the action will be taken (if it’s on and I activate the ‘off’ scene, it turns off and vice versa), and then immediately afterwards, it changes to ‘dead’. It SEEMS to be reproducible - if I reboot the RPi, and a node comes up as alive, if I activate the scene for that node that is opposite its current state (We have cameras there, so I can see what’s happening remotely), the action is taken and then afterwards, the node shows up as dead. So far, it SEEMS like the only node that has been coming online on reboot is one of the upstairs nodes, and the one that is probably the furthest away at that, not the closest, line of sight node.

Here’s the OZW_Log from one such instance - from reboot to activating the scene to device ‘dead’.

2018-05-27 00:16:26.248 Always, OpenZwave Version 1.4.2926 Starting Up
2018-05-27 00:16:27.810 Info, Setting Up Provided Network Key for Secure Communications
2018-05-27 00:16:27.817 Info, mgr,     Added driver for controller /dev/ttyS0
2018-05-27 00:16:27.817 Info,   Opening controller /dev/ttyS0
2018-05-27 00:16:27.817 Info, Trying to open serial port /dev/ttyS0 (attempt 1)
2018-05-27 00:16:27.817 Info, Serial port /dev/ttyS0 opened (attempt 1)
2018-05-27 00:16:27.817 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-05-27 00:16:27.817 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-05-27 00:16:27.818 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-05-27 00:16:27.818 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-05-27 00:16:27.818 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-05-27 00:16:27.818 Detail, 
2018-05-27 00:16:27.818 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-05-27 00:16:27.821 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x30, 0x35, 0x00, 0x01, 0x97
2018-05-27 00:16:27.821 Detail, 
2018-05-27 00:16:27.821 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2018-05-27 00:16:27.821 Info, contrlr,     Static Controller library, version Z-Wave 4.05
2018-05-27 00:16:27.821 Detail, Node045,   Expected reply was received
2018-05-27 00:16:27.821 Detail, Node045,   Message transaction complete
2018-05-27 00:16:27.821 Detail, 
2018-05-27 00:16:27.821 Detail, contrlr, Removing current message
2018-05-27 00:16:27.821 Detail, 
2018-05-27 00:16:27.821 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-05-27 00:16:27.827 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xcf, 0x1a, 0x77, 0x16, 0x01, 0x63
2018-05-27 00:16:27.828 Detail, 
2018-05-27 00:16:27.828 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xcf1a7716.  Our node ID = 1
2018-05-27 00:16:27.828 Detail, Node026,   Expected reply was received
2018-05-27 00:16:27.828 Detail, Node026,   Message transaction complete
2018-05-27 00:16:27.828 Detail, 
2018-05-27 00:16:27.828 Detail, contrlr, Removing current message
2018-05-27 00:16:27.828 Detail, 
2018-05-27 00:16:27.828 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-05-27 00:16:27.829 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x08, 0xf7
2018-05-27 00:16:27.831 Detail, 
2018-05-27 00:16:27.831 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2018-05-27 00:16:27.831 Info, contrlr,     There is no SUC ID Server (SIS) in this network.
2018-05-27 00:16:27.831 Info, contrlr,     The PC controller is a primary controller.
2018-05-27 00:16:27.831 Detail, Node247,   Expected reply was received
2018-05-27 00:16:27.831 Detail, Node247,   Message transaction complete
2018-05-27 00:16:27.831 Detail, 
2018-05-27 00:16:27.831 Detail, contrlr, Removing current message
2018-05-27 00:16:27.831 Detail, 
2018-05-27 00:16:27.831 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-05-27 00:16:27.836 Detail, contrlr,   Received: 0x01, 0x2b, 0x01, 0x07, 0x05, 0x04, 0x01, 0x47, 0x04, 0x00, 0x00, 0x02, 0xfe, 0x83, 0xff, 0x88, 0xcf, 0x1f, 0x00, 0x00, 0xfb, 0x9f, 0x7d, 0xa0, 0x67, 0x00, 0x80, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xe8, 0x73, 0x00, 0x00, 0x0e, 0x00, 0x00, 0x40, 0x1a, 0x00, 0x5e
2018-05-27 00:16:27.836 Detail, 
2018-05-27 00:16:27.836 Info, contrlr,  Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2018-05-27 00:16:27.836 Info, contrlr,     Serial API Version:   5.4
2018-05-27 00:16:27.836 Info, contrlr,     Manufacturer ID:      0x0147
2018-05-27 00:16:27.837 Info, contrlr,     Product Type:         0x0400
2018-05-27 00:16:27.837 Info, contrlr,     Product ID:           0x0002
2018-05-27 00:16:27.837 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2018-05-27 00:16:27.837 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2018-05-27 00:16:27.837 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2018-05-27 00:16:27.837 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2018-05-27 00:16:27.837 Detail, Node004,   Expected reply was received
2018-05-27 00:16:27.837 Detail, Node004,   Message transaction complete
2018-05-27 00:16:27.837 Detail, 
2018-05-27 00:16:27.837 Detail, contrlr, Removing current message
2018-05-27 00:16:27.837 Detail, 
2018-05-27 00:16:27.837 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-05-27 00:16:27.838 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2018-05-27 00:16:27.839 Detail, 
2018-05-27 00:16:27.839 Info, contrlr, Received reply to GET_SUC_NODE_ID.  Node ID = 0
2018-05-27 00:16:27.839 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node
2018-05-27 00:16:27.839 Detail, Node172,   Expected reply was received
2018-05-27 00:16:27.839 Detail, Node172,   Message transaction complete
2018-05-27 00:16:27.839 Detail, 
2018-05-27 00:16:27.839 Detail, contrlr, Removing current message
2018-05-27 00:16:27.839 Detail, 
2018-05-27 00:16:27.839 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2018-05-27 00:16:27.893 Detail, contrlr,   Received: 0x01, 0x25, 0x01, 0x1c, 0x01, 0x20, 0x3c, 0x2e, 0xe4, 0xe5, 0xff, 0x8b, 0xff, 0x72, 0x96, 0x16, 0x67, 0x4c, 0x59, 0x9e, 0xae, 0x4b, 0x1f, 0x48, 0x04, 0x8c, 0x72, 0xb1, 0xf4, 0x7a, 0xde, 0xac, 0xc5, 0x07, 0x09, 0x03, 0xc5, 0x59, 0x31
2018-05-27 00:16:27.893 Detail, 
2018-05-27 00:16:27.893 Info, contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2018-05-27 00:16:27.893 Detail, Node032,   Expected reply was received
2018-05-27 00:16:27.893 Detail, Node032,   Message transaction complete
2018-05-27 00:16:27.893 Detail, 
2018-05-27 00:16:27.893 Detail, contrlr, Removing current message
2018-05-27 00:16:27.893 Detail, 
2018-05-27 00:16:27.893 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x02) - FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2018-05-27 00:16:27.952 Detail, contrlr,   Received: 0x01, 0x25, 0x01, 0x02, 0x05, 0x00, 0x1d, 0x39, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x05, 0x00, 0xfd
2018-05-27 00:16:27.952 Detail, 
2018-05-27 00:16:27.952 Info, mgr,     Driver with Home ID of 0xcf1a7716 is now ready.
2018-05-27 00:16:27.952 Info, 
2018-05-27 00:16:27.966 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2018-05-27 00:16:27.966 Info, contrlr,     Node 001 - Known
2018-05-27 00:16:27.966 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-27 00:16:27.966 Detail, Node001, QueryStage_CacheLoad
2018-05-27 00:16:27.966 Info, Node001, Node Identity Codes: 0147:0400:0002
2018-05-27 00:16:27.966 Detail, Node001, QueryStage_Associations
2018-05-27 00:16:27.966 Detail, Node001, QueryStage_Neighbors
2018-05-27 00:16:27.966 Detail, contrlr, Requesting routing info (neighbor list) for Node 1
2018-05-27 00:16:27.966 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2018-05-27 00:16:27.966 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2018-05-27 00:16:27.966 Info, contrlr,     Node 004 - Known
2018-05-27 00:16:27.966 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-27 00:16:27.966 Detail, Node004, QueryStage_CacheLoad
2018-05-27 00:16:27.967 Info, Node004, Node Identity Codes: 0000:0000:0000
2018-05-27 00:16:27.967 Info, Node004, NoOperation::Set - Routing=true
2018-05-27 00:16:27.967 Detail, Node004, Queuing (NoOp) NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xcc
2018-05-27 00:16:27.967 Detail, Node004, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-27 00:16:27.967 Info, contrlr,     Node 005 - Known
2018-05-27 00:16:27.967 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-27 00:16:27.967 Detail, Node005, QueryStage_CacheLoad
2018-05-27 00:16:27.967 Info, Node005, Node Identity Codes: 0000:0000:0000
2018-05-27 00:16:27.967 Info, Node005, NoOperation::Set - Routing=true
2018-05-27 00:16:27.967 Detail, Node005, Queuing (NoOp) NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x0b, 0xcc
2018-05-27 00:16:27.967 Detail, Node005, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-27 00:16:27.967 Info, contrlr,     Node 006 - Known
2018-05-27 00:16:27.967 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-05-27 00:16:27.967 Detail, Node006, QueryStage_CacheLoad
2018-05-27 00:16:27.967 Info, Node006, Node Identity Codes: 001d:0602:0334
2018-05-27 00:16:27.967 Info, Node006, NoOperation::Set - Routing=true
2018-05-27 00:16:27.967 Detail, Node006, Queuing (NoOp) NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xc8
2018-05-27 00:16:27.967 Detail, Node006, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-27 00:16:27.967 Detail,   Expected reply was received
2018-05-27 00:16:27.968 Detail,   Message transaction complete
-SNIP-
2018-05-27 00:16:28.186 Detail, 
2018-05-27 00:16:28.186 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x06) - FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2018-05-27 00:16:28.187 Detail, contrlr,   Received: 0x01, 0x05, 0x01, 0x06, 0x64, 0x0f, 0x96
2018-05-27 00:16:28.188 Detail, 
2018-05-27 00:16:28.188 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_SET_TIMEOUTS
2018-05-27 00:16:28.188 Detail, Node015,   Expected reply was received
2018-05-27 00:16:28.188 Detail, Node015,   Message transaction complete
2018-05-27 00:16:28.188 Detail, 
2018-05-27 00:16:28.188 Detail, contrlr, Removing current message
2018-05-27 00:16:28.188 Detail, 
2018-05-27 00:16:28.188 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x00) - FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2018-05-27 00:16:28.189 Detail, contrlr, Removing current message
2018-05-27 00:16:28.189 Detail, 
2018-05-27 00:16:28.189 Info, Node001, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2018-05-27 00:16:28.194 Detail, Node001,   Received: 0x01, 0x20, 0x01, 0x80, 0x20, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x7e
2018-05-27 00:16:28.198 Detail, 
2018-05-27 00:16:28.198 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-05-27 00:16:28.198 Info, Node001,     Neighbors of this node are:
2018-05-27 00:16:28.198 Info, Node001,     Node 6
2018-05-27 00:16:28.198 Detail,   Expected reply was received
2018-05-27 00:16:28.198 Detail,   Message transaction complete
2018-05-27 00:16:28.198 Detail, 
2018-05-27 00:16:28.198 Detail, Node001, Removing current message
2018-05-27 00:16:28.198 Detail, 
2018-05-27 00:16:28.198 Info, Node004, Sending (NoOp) message (Callback ID=0x0a, Expected Reply=0x13) - NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xcc
2018-05-27 00:16:28.263 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:28.263 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:32.627 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x0a, 0x01, 0x01, 0xba, 0x5b
2018-05-27 00:16:32.627 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x0a received (expected 0x0a)
2018-05-27 00:16:32.627 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:16:32.627 Warning, Node004, WARNING: Device is not a sleeping node.
2018-05-27 00:16:32.627 Info, Node004, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 0 pending 1
2018-05-27 00:16:32.627 Detail, Node001,   Expected callbackId was received
2018-05-27 00:16:32.627 Detail, Node001,   Expected reply was received
2018-05-27 00:16:32.627 Detail, Node001,   Message transaction complete
2018-05-27 00:16:32.627 Detail, 
2018-05-27 00:16:32.627 Detail, Node004, Removing current message
2018-05-27 00:16:32.628 Detail, Node004, Notification: Notification - NoOperation
2018-05-27 00:16:32.631 Detail, 
2018-05-27 00:16:32.631 Info, Node005, Sending (NoOp) message (Callback ID=0x0b, Expected Reply=0x13) - NoOperation_Set (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x00, 0x00, 0x25, 0x0b, 0xcc
2018-05-27 00:16:32.696 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:32.696 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:42.631 Error, Node005, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-05-27 00:16:42.632 Detail, Node005, Removing current message
2018-05-27 00:16:42.632 Detail, Node005, Notification: Notification - TimeOut
2018-05-27 00:16:42.634 Detail, 
2018-05-27 00:16:42.637 Info, Node006, Sending (NoOp) message (Callback ID=0x0c, Expected Reply=0x13) - NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xc8
2018-05-27 00:16:42.644 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:42.644 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:43.596 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x0c, 0x01, 0x00, 0x60, 0x86
2018-05-27 00:16:43.596 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x0c received (expected 0x0c)
2018-05-27 00:16:43.596 Info, Node006, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:16:43.596 Warning, Node006, WARNING: Device is not a sleeping node.
2018-05-27 00:16:43.596 Info, Node006, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 0 pending 1
2018-05-27 00:16:43.596 Detail, Node001,   Expected callbackId was received
2018-05-27 00:16:43.596 Detail, Node001,   Expected reply was received
2018-05-27 00:16:43.596 Detail, Node001,   Message transaction complete
2018-05-27 00:16:43.596 Detail, 
2018-05-27 00:16:43.596 Detail, Node006, Removing current message
2018-05-27 00:16:43.596 Detail, Node006, Notification: Notification - NoOperation
2018-05-27 00:16:43.599 Detail, Node001, Query Stage Complete (Neighbors)
2018-05-27 00:16:43.601 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2018-05-27 00:16:43.601 Detail, Node001, QueryStage_Session
2018-05-27 00:16:43.601 Detail, Node001, QueryStage_Dynamic
2018-05-27 00:16:43.601 Detail, Node001, QueryStage_Configuration
2018-05-27 00:16:43.601 Detail, Node001, QueryStage_Complete
2018-05-27 00:16:43.601 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-27 00:16:43.602 Warning, CheckCompletedNodeQueries all=0, deadFound=0 sleepingOnly=0
2018-05-27 00:16:43.602 Detail, Node001, Notification: NodeQueriesComplete
2018-05-27 00:16:43.605 Detail, Node004, Query Stage Complete (CacheLoad)
2018-05-27 00:16:43.605 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=1 queryStage=CacheLoad live=1
2018-05-27 00:16:43.605 Detail, Node004, QueryStage_CacheLoad
2018-05-27 00:16:43.605 Info, Node004, Node Identity Codes: 0000:0000:0000
2018-05-27 00:16:43.605 Info, Node004, NoOperation::Set - Routing=true
2018-05-27 00:16:43.605 Detail, Node004, Queuing (NoOp) NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0d, 0xcb
2018-05-27 00:16:43.605 Detail, Node004, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-27 00:16:43.605 Detail, 
2018-05-27 00:16:43.606 Info, Node004, Sending (NoOp) message (Callback ID=0x0d, Expected Reply=0x13) - NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0d, 0xcb
2018-05-27 00:16:43.670 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:43.671 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:46.939 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x01, 0x01, 0x4d, 0xab
2018-05-27 00:16:46.940 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d)
2018-05-27 00:16:46.940 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:16:46.940 Warning, Node004, WARNING: Device is not a sleeping node.
2018-05-27 00:16:46.940 Info, Node004, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 1 pending 1
2018-05-27 00:16:46.940 Detail, Node001,   Expected callbackId was received
2018-05-27 00:16:46.940 Detail, Node001,   Expected reply was received
2018-05-27 00:16:46.940 Detail, Node001,   Message transaction complete
2018-05-27 00:16:46.940 Detail, 
2018-05-27 00:16:46.940 Detail, Node004, Removing current message
2018-05-27 00:16:46.941 Detail, Node004, Notification: Notification - NoOperation
2018-05-27 00:16:46.943 Detail, Node005, Query Stage Complete (CacheLoad)
2018-05-27 00:16:46.943 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Associations live=1
2018-05-27 00:16:46.943 Detail, Node005, QueryStage_Associations
2018-05-27 00:16:46.944 Detail, Node005, QueryStage_Neighbors
2018-05-27 00:16:46.944 Detail, Requesting routing info (neighbor list) for Node 5
2018-05-27 00:16:46.944 Detail, Node005, Queuing (Command) Get Routing Info (Node=5): 0x01, 0x07, 0x00, 0x80, 0x05, 0x00, 0x00, 0x03, 0x7e
2018-05-27 00:16:46.944 Detail, Node005, Queuing (Query) Query Stage Complete (Neighbors)
2018-05-27 00:16:46.944 Detail, 
2018-05-27 00:16:46.944 Info, Node005, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=5): 0x01, 0x07, 0x00, 0x80, 0x05, 0x00, 0x00, 0x03, 0x7e
2018-05-27 00:16:46.949 Detail, Node005,   Received: 0x01, 0x20, 0x01, 0x80, 0x28, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x76
2018-05-27 00:16:46.949 Detail, 
2018-05-27 00:16:46.950 Info, Node005, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-05-27 00:16:46.950 Info, Node005,     Neighbors of this node are:
2018-05-27 00:16:46.950 Info, Node005,     Node 4
2018-05-27 00:16:46.950 Info, Node005,     Node 6
2018-05-27 00:16:46.950 Detail,   Expected reply was received
2018-05-27 00:16:46.950 Detail,   Message transaction complete
2018-05-27 00:16:46.950 Detail, 
2018-05-27 00:16:46.950 Detail, Node005, Removing current message
2018-05-27 00:16:46.950 Detail, Node006, Query Stage Complete (CacheLoad)
2018-05-27 00:16:46.950 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=1 queryStage=CacheLoad live=1
2018-05-27 00:16:46.950 Detail, Node006, QueryStage_CacheLoad
2018-05-27 00:16:46.950 Info, Node006, Node Identity Codes: 001d:0602:0334
2018-05-27 00:16:46.950 Info, Node006, NoOperation::Set - Routing=true
2018-05-27 00:16:46.951 Detail, Node006, Queuing (NoOp) NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0e, 0xca
2018-05-27 00:16:46.951 Detail, Node006, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-27 00:16:46.951 Detail, 
2018-05-27 00:16:46.951 Info, Node006, Sending (NoOp) message (Callback ID=0x0e, Expected Reply=0x13) - NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x0e, 0xca
2018-05-27 00:16:46.958 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:46.958 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:47.960 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x0e, 0x01, 0x00, 0x64, 0x80
2018-05-27 00:16:47.960 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x0e received (expected 0x0e)
2018-05-27 00:16:47.960 Info, Node006, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:16:47.960 Warning, Node006, WARNING: Device is not a sleeping node.
2018-05-27 00:16:47.960 Info, Node006, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 1 pending 1
2018-05-27 00:16:47.960 Detail, Node001,   Expected callbackId was received
2018-05-27 00:16:47.960 Detail, Node001,   Expected reply was received
2018-05-27 00:16:47.960 Detail, Node001,   Message transaction complete
2018-05-27 00:16:47.960 Detail, 
2018-05-27 00:16:47.960 Detail, Node006, Removing current message
2018-05-27 00:16:47.960 Detail, Node006, Notification: Notification - NoOperation
2018-05-27 00:16:47.963 Detail, Node004, Query Stage Complete (CacheLoad)
2018-05-27 00:16:47.964 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=2 queryStage=CacheLoad live=1
2018-05-27 00:16:47.964 Detail, Node004, QueryStage_CacheLoad
2018-05-27 00:16:47.964 Info, Node004, Node Identity Codes: 0000:0000:0000
2018-05-27 00:16:47.964 Info, Node004, NoOperation::Set - Routing=true
2018-05-27 00:16:47.964 Detail, Node004, Queuing (NoOp) NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0f, 0xc9
2018-05-27 00:16:47.964 Detail, Node004, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-27 00:16:47.964 Detail, 
2018-05-27 00:16:47.964 Info, Node004, Sending (NoOp) message (Callback ID=0x0f, Expected Reply=0x13) - NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0f, 0xc9
2018-05-27 00:16:48.029 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:48.029 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:51.239 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x0f, 0x01, 0x01, 0x47, 0xa3
2018-05-27 00:16:51.240 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x0f received (expected 0x0f)
2018-05-27 00:16:51.240 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:16:51.243 Warning, Node004, WARNING: Device is not a sleeping node.
2018-05-27 00:16:51.243 Error, Node004, ERROR: node presumed dead
2018-05-27 00:16:51.243 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-27 00:16:51.243 Warning, CheckCompletedNodeQueries all=0, deadFound=1 sleepingOnly=0
2018-05-27 00:16:51.243 Info, Node004, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 2 pending 1
2018-05-27 00:16:51.243 Detail, Node001,   Expected callbackId was received
2018-05-27 00:16:51.243 Detail, Node001,   Expected reply was received
2018-05-27 00:16:51.243 Detail, Node001,   Message transaction complete
2018-05-27 00:16:51.243 Detail, 
2018-05-27 00:16:51.243 Detail, Node004, Removing current message
2018-05-27 00:16:51.243 Detail, Node004, Notification: Notification - NoOperation
2018-05-27 00:16:51.245 Detail, Node004, Notification: Notification - Node Dead
2018-05-27 00:16:51.248 Detail, Node005, Query Stage Complete (Neighbors)
2018-05-27 00:16:51.248 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2018-05-27 00:16:51.248 Detail, Node005, QueryStage_Session
2018-05-27 00:16:51.248 Detail, Node005, Queuing (Query) SwitchAllCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x27, 0x02, 0x25, 0x10, 0xf2
2018-05-27 00:16:51.248 Detail, Node005, Queuing (Query) Query Stage Complete (Session)
2018-05-27 00:16:51.248 Detail, Node006, Query Stage Complete (CacheLoad)
2018-05-27 00:16:51.248 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=2 queryStage=CacheLoad live=1
2018-05-27 00:16:51.248 Detail, Node006, QueryStage_CacheLoad
2018-05-27 00:16:51.248 Info, Node006, Node Identity Codes: 001d:0602:0334
2018-05-27 00:16:51.248 Info, Node006, NoOperation::Set - Routing=true
2018-05-27 00:16:51.248 Detail, Node006, Queuing (NoOp) NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x11, 0xd5
2018-05-27 00:16:51.248 Detail, Node006, Queuing (Query) Query Stage Complete (CacheLoad)
2018-05-27 00:16:51.248 Detail, 
2018-05-27 00:16:51.248 Info, Node006, Sending (NoOp) message (Callback ID=0x11, Expected Reply=0x13) - NoOperation_Set (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x00, 0x00, 0x25, 0x11, 0xd5
2018-05-27 00:16:51.256 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:51.259 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:52.408 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x11, 0x01, 0x00, 0x73, 0x88
2018-05-27 00:16:52.408 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x11 received (expected 0x11)
2018-05-27 00:16:52.408 Info, Node006, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:16:52.408 Warning, Node006, WARNING: Device is not a sleeping node.
2018-05-27 00:16:52.408 Error, Node006, ERROR: node presumed dead
2018-05-27 00:16:52.408 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-27 00:16:52.408 Warning, CheckCompletedNodeQueries all=0, deadFound=1 sleepingOnly=0
2018-05-27 00:16:52.408 Info, Node006, QueryStageRetry stage CacheLoad requested stage CacheLoad max 3 retries 2 pending 1
2018-05-27 00:16:52.408 Detail, Node001,   Expected callbackId was received
2018-05-27 00:16:52.408 Detail, Node001,   Expected reply was received
2018-05-27 00:16:52.409 Detail, Node001,   Message transaction complete
2018-05-27 00:16:52.409 Detail, 
2018-05-27 00:16:52.409 Detail, Node006, Removing current message
2018-05-27 00:16:52.409 Detail, Node006, Notification: Notification - NoOperation
2018-05-27 00:16:52.412 Detail, Node006, Notification: Notification - Node Dead
2018-05-27 00:16:52.414 Detail, Node004, Query Stage Complete (CacheLoad)
2018-05-27 00:16:52.415 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=0
2018-05-27 00:16:52.415 Detail, 
2018-05-27 00:16:52.415 Info, Node005, Sending (Query) message (Callback ID=0x10, Expected Reply=0x04) - SwitchAllCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x27, 0x02, 0x25, 0x10, 0xf2
2018-05-27 00:16:52.480 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:16:52.480 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:16:55.448 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x10, 0x01, 0x01, 0x2f, 0xd4
2018-05-27 00:16:55.448 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x10 received (expected 0x10)
2018-05-27 00:16:55.448 Info, Node005, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:16:55.448 Warning, Node005, WARNING: Device is not a sleeping node.
2018-05-27 00:16:55.448 Detail, Node001,   Expected callbackId was received
2018-05-27 00:16:56.862 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x10, 0x01, 0x01, 0xbd, 0x46
2018-05-27 00:16:56.862 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x10 received (expected 0x00)
2018-05-27 00:16:56.862 Warning, Node005, WARNING: Unexpected Callback ID received
2018-05-27 00:17:02.416 Error, Node005, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-05-27 00:17:02.416 Detail, Node005, Removing current message
2018-05-27 00:17:02.417 Detail, Node005, Notification: Notification - TimeOut
2018-05-27 00:17:02.419 Detail, Node005, Query Stage Complete (Session)
2018-05-27 00:17:02.419 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2018-05-27 00:17:02.420 Detail, Node005, QueryStage_Dynamic
2018-05-27 00:17:02.420 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x12, 0xf1
2018-05-27 00:17:02.420 Detail, Node005, Queuing (Query) Query Stage Complete (Dynamic)
2018-05-27 00:17:02.420 Detail, 
2018-05-27 00:17:02.420 Info, Node005, Sending (Send) message (Callback ID=0x12, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x12, 0xf1

Cougar281 · May 27, 2018, 5:21am

code part 2

2018-05-27 00:17:02.485 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:17:02.485 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:17:06.864 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x12, 0x01, 0x01, 0xbc, 0x45
2018-05-27 00:17:06.864 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x12 received (expected 0x12)
2018-05-27 00:17:06.864 Info, Node005, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:17:06.864 Warning, Node005, WARNING: Device is not a sleeping node.
2018-05-27 00:17:06.864 Detail, Node001,   Expected callbackId was received
2018-05-27 00:17:12.420 Error, Node005, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-05-27 00:17:12.421 Detail, Node005, Removing current message
2018-05-27 00:17:12.421 Detail, Node005, Notification: Notification - TimeOut
2018-05-27 00:17:12.424 Detail, Node006, Query Stage Complete (CacheLoad)
2018-05-27 00:17:12.424 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=0
2018-05-27 00:17:12.424 Detail, Node005, Query Stage Complete (Dynamic)
2018-05-27 00:17:12.424 Detail, Node005, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2018-05-27 00:17:12.424 Detail, Node005, QueryStage_Configuration
2018-05-27 00:17:12.424 Detail, Node005, QueryStage_Complete
2018-05-27 00:17:12.424 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-05-27 00:17:12.424 Warning, CheckCompletedNodeQueries all=1, deadFound=1 sleepingOnly=1
2018-05-27 00:17:12.425 Info,          Node query processing complete except for dead nodes.
2018-05-27 00:17:12.425 Detail, Node005, Notification: NodeQueriesComplete
2018-05-27 00:17:12.427 Detail, contrlr, Notification: AllNodesQueriedSomeDead
2018-05-27 00:17:16.564 Info, Node005, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 0
2018-05-27 00:17:16.565 Info, Node005, SwitchMultilevel::Set - Setting to level 0
2018-05-27 00:17:16.565 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0x00, 0x25, 0x13, 0xf1
2018-05-27 00:17:16.565 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x14, 0xf7
2018-05-27 00:17:16.566 Detail, 
2018-05-27 00:17:16.566 Info, Node005, Sending (Send) message (Callback ID=0x13, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0x00, 0x25, 0x13, 0xf1
2018-05-27 00:17:16.631 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-27 00:17:16.631 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-27 00:17:17.567 Info, mgr,     Refreshing node 5: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-27 00:17:17.567 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x15, 0xf6
2018-05-27 00:17:18.568 Info, mgr,     Refreshing node 5: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-27 00:17:18.568 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x16, 0xf5
2018-05-27 00:17:20.952 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x13, 0x01, 0x01, 0xb7, 0x4f
2018-05-27 00:17:20.952 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x13 received (expected 0x13)
2018-05-27 00:17:20.952 Info, Node005, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-05-27 00:17:20.952 Warning, Node005, WARNING: Device is not a sleeping node.
2018-05-27 00:17:20.952 Error, Node005, ERROR: node presumed dead
2018-05-27 00:17:20.952 Detail, Node001,   Expected callbackId was received
2018-05-27 00:17:20.953 Detail, Node001,   Expected reply was received
2018-05-27 00:17:20.953 Detail, Node001,   Message transaction complete
2018-05-27 00:17:20.953 Detail, 
2018-05-27 00:17:20.953 Detail, Node005, Removing current message
2018-05-27 00:17:20.953 Detail, Node005, Notification: Notification - Node Dead
2018-05-27 00:17:20.956 Error, Node005, ERROR: Dropping command because node is presumed dead
2018-05-27 00:17:20.956 Detail, Node005, Removing current message
2018-05-27 00:17:20.956 Error, Node005, ERROR: Dropping command because node is presumed dead
2018-05-27 00:17:20.956 Detail, Node005, Removing current message
2018-05-27 00:17:20.956 Error, Node005, ERROR: Dropping command because node is presumed dead
2018-05-27 00:17:20.956 Detail, Node005, Removing current message

firstof9 · May 27, 2018, 2:08pm

This doesn’t look right.
I don’t think it’s the controller, try excluding and repairing the devices.

Cougar281 · May 28, 2018, 1:08pm

I swapped the original card back in and it was doing the exact same thing - is it possible that the rename of the nodes made some kind of change to the config on the controller? While I had some issues with nodes dropping off before, since I moved it to where it is now, it’s been solid (Until the swap and node rename).

What I might do is reset all the switches to default and also reset the controller do default using the Z-Way software and re-pair the switches.

firstof9 · May 28, 2018, 3:19pm

Give it a shot, fyi don’t use the node rename anymore you can rename zwave devices via entity_registry.yaml now

Cougar281 · May 28, 2018, 3:51pm

I’ll have to try that - last time I did, it essentially voided the entries with the changes and created new, duplicate ones lol.

firstof9 · May 28, 2018, 4:12pm

Note you are able to rename some devices via the UI. Via the <> menu. There’s a little box one the left side of objects, and ones you can rename will have a cog next to their name. I used that for quite a few devices.

Cougar281 · June 2, 2018, 2:02am

So I did a factory reset on the Razberry, as well as all of the switches (They wouldn’t re-associate without a reset :/), and while I was at it, I added two Aeotec plug in modules to add to the mesh for grins. Everything seems to be working perfectly again. I can’t really explain it, but since it’s the only thing ‘out of the ordinary’ that I did before it went sideways, it SEEMS to me like somehow, renaming the nodes in the ZWave menu managed to bork the controller config. It seems liek all but one node can directly see the contoller, based on the logs from a heal.

2018-06-01 20:57:21.819 Detail, Node001, Queuing (Controller) Request Node Neighbor Update
2018-06-01 20:57:21.819 Detail, Node002, Queuing (Controller) Request Node Neighbor Update
2018-06-01 20:57:21.819 Info, Requesting Neighbor Update for node 1
2018-06-01 20:57:21.820 Detail, Node003, Queuing (Controller) Request Node Neighbor Update
2018-06-01 20:57:21.820 Detail, Node004, Queuing (Controller) Request Node Neighbor Update
2018-06-01 20:57:21.820 Detail, Node005, Queuing (Controller) Request Node Neighbor Update
2018-06-01 20:57:21.820 Detail, Node006, Queuing (Controller) Request Node Neighbor Update
2018-06-01 20:57:21.820 Detail, Node001, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x43, 0xf0
2018-06-01 20:57:21.820 Detail, Notification: ControllerCommand - Starting
2018-06-01 20:57:21.821 Detail, 
2018-06-01 20:57:21.821 Info, Node001, Sending (Command) message (Callback ID=0x43, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x43, 0xf0
2018-06-01 20:57:21.844 Detail, Node001,   Received: 0x01, 0x05, 0x00, 0x48, 0x43, 0x21, 0xd0
2018-06-01 20:57:21.844 Detail, 
2018-06-01 20:57:21.844 Info, Node001, REQUEST_NEIGHBOR_UPDATE_STARTED
2018-06-01 20:57:21.844 Detail, Node033,   Expected callbackId was received
2018-06-01 20:57:21.844 Detail, Node033,   Expected reply was received
2018-06-01 20:57:21.844 Detail, Node033,   Message transaction complete
2018-06-01 20:57:21.844 Detail, 
2018-06-01 20:57:21.844 Detail, Node001, Removing current message
2018-06-01 20:57:21.845 Detail, Notification: ControllerCommand - InProgress
2018-06-01 20:57:21.845 Info, WriteNextMsg Controller nothing to do
2018-06-01 20:57:33.599 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x43, 0x23, 0xd2
2018-06-01 20:57:33.600 Detail, 
2018-06-01 20:57:33.600 Warning, WARNING: REQUEST_NEIGHBOR_UPDATE_FAILED
2018-06-01 20:57:33.600 Detail, Notification: ControllerCommand - Failed
2018-06-01 20:57:33.601 Info, Requesting Neighbor Update for node 2
2018-06-01 20:57:33.601 Detail, Node002, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=2): 0x01, 0x05, 0x00, 0x48, 0x02, 0x44, 0xf4
2018-06-01 20:57:33.601 Detail, Notification: ControllerCommand - Starting
2018-06-01 20:57:33.601 Detail, 
2018-06-01 20:57:33.602 Info, Node002, Sending (Command) message (Callback ID=0x44, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=2): 0x01, 0x05, 0x00, 0x48, 0x02, 0x44, 0xf4
2018-06-01 20:57:33.626 Detail, Node002,   Received: 0x01, 0x05, 0x00, 0x48, 0x44, 0x21, 0xd7
2018-06-01 20:57:33.626 Detail, 
2018-06-01 20:57:33.626 Info, Node002, REQUEST_NEIGHBOR_UPDATE_STARTED
2018-06-01 20:57:33.626 Detail, Node033,   Expected callbackId was received
2018-06-01 20:57:33.626 Detail, Node033,   Expected reply was received
2018-06-01 20:57:33.626 Detail, Node033,   Message transaction complete
2018-06-01 20:57:33.626 Detail, 
2018-06-01 20:57:33.627 Detail, Node002, Removing current message
2018-06-01 20:57:33.627 Detail, Notification: ControllerCommand - InProgress
2018-06-01 20:57:33.627 Info, WriteNextMsg Controller nothing to do
2018-06-01 20:57:34.839 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x44, 0x22, 0xd4
2018-06-01 20:57:34.839 Detail, 
2018-06-01 20:57:34.839 Info, REQUEST_NEIGHBOR_UPDATE_DONE
2018-06-01 20:57:34.839 Detail, Requesting routing info (neighbor list) for Node 2
2018-06-01 20:57:34.839 Detail, Node002, Queuing (Command) Get Routing Info (Node=2): 0x01, 0x07, 0x00, 0x80, 0x02, 0x00, 0x00, 0x03, 0x79
2018-06-01 20:57:34.839 Detail, Notification: ControllerCommand - Completed
2018-06-01 20:57:34.840 Detail, 
2018-06-01 20:57:34.840 Info, Node002, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=2): 0x01, 0x07, 0x00, 0x80, 0x02, 0x00, 0x00, 0x03, 0x79
2018-06-01 20:57:34.848 Detail, Node002,   Received: 0x01, 0x20, 0x01, 0x80, 0x3d, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x63
2018-06-01 20:57:34.849 Detail, 
2018-06-01 20:57:34.849 Info, Node002, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-06-01 20:57:34.849 Info, Node002,     Neighbors of this node are:
2018-06-01 20:57:34.849 Info, Node002,     Node 1
2018-06-01 20:57:34.849 Info, Node002,     Node 3
2018-06-01 20:57:34.849 Info, Node002,     Node 4
2018-06-01 20:57:34.849 Info, Node002,     Node 5
2018-06-01 20:57:34.849 Info, Node002,     Node 6
2018-06-01 20:57:34.849 Detail,   Expected reply was received
2018-06-01 20:57:34.849 Detail,   Message transaction complete
2018-06-01 20:57:34.849 Detail, 
2018-06-01 20:57:34.849 Detail, Node002, Removing current message
2018-06-01 20:57:34.850 Info, Requesting Neighbor Update for node 3
2018-06-01 20:57:34.850 Detail, Node003, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=3): 0x01, 0x05, 0x00, 0x48, 0x03, 0x45, 0xf4
2018-06-01 20:57:34.850 Detail, Notification: ControllerCommand - Starting
2018-06-01 20:57:34.850 Detail, 
2018-06-01 20:57:34.850 Info, Node003, Sending (Command) message (Callback ID=0x45, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=3): 0x01, 0x05, 0x00, 0x48, 0x03, 0x45, 0xf4
2018-06-01 20:57:34.875 Detail, Node003,   Received: 0x01, 0x05, 0x00, 0x48, 0x45, 0x21, 0xd6
2018-06-01 20:57:34.875 Detail, 
2018-06-01 20:57:34.875 Info, Node003, REQUEST_NEIGHBOR_UPDATE_STARTED
2018-06-01 20:57:34.875 Detail, Node033,   Expected callbackId was received
2018-06-01 20:57:34.875 Detail, Node033,   Expected reply was received
2018-06-01 20:57:34.875 Detail, Node033,   Message transaction complete
2018-06-01 20:57:34.875 Detail, 
2018-06-01 20:57:34.876 Detail, Node003, Removing current message
2018-06-01 20:57:34.876 Detail, Notification: ControllerCommand - InProgress
2018-06-01 20:57:34.876 Info, WriteNextMsg Controller nothing to do
2018-06-01 20:57:35.876 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x45, 0x22, 0xd5
2018-06-01 20:57:35.876 Detail, 
2018-06-01 20:57:35.876 Info, REQUEST_NEIGHBOR_UPDATE_DONE
2018-06-01 20:57:35.876 Detail, Requesting routing info (neighbor list) for Node 3
2018-06-01 20:57:35.876 Detail, Node003, Queuing (Command) Get Routing Info (Node=3): 0x01, 0x07, 0x00, 0x80, 0x03, 0x00, 0x00, 0x03, 0x78
2018-06-01 20:57:35.876 Detail, Notification: ControllerCommand - Completed
2018-06-01 20:57:35.877 Detail, 
2018-06-01 20:57:35.877 Info, Node003, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=3): 0x01, 0x07, 0x00, 0x80, 0x03, 0x00, 0x00, 0x03, 0x78
2018-06-01 20:57:35.885 Detail, Node003,   Received: 0x01, 0x20, 0x01, 0x80, 0x3b, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x65
2018-06-01 20:57:35.886 Detail, 
2018-06-01 20:57:35.886 Info, Node003, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-06-01 20:57:35.886 Info, Node003,     Neighbors of this node are:
2018-06-01 20:57:35.886 Info, Node003,     Node 1
2018-06-01 20:57:35.886 Info, Node003,     Node 2
2018-06-01 20:57:35.886 Info, Node003,     Node 4
2018-06-01 20:57:35.886 Info, Node003,     Node 5
2018-06-01 20:57:35.886 Info, Node003,     Node 6
2018-06-01 20:57:35.886 Detail,   Expected reply was received
2018-06-01 20:57:35.886 Detail,   Message transaction complete
2018-06-01 20:57:35.886 Detail, 
2018-06-01 20:57:35.886 Detail, Node003, Removing current message
2018-06-01 20:57:35.887 Info, Requesting Neighbor Update for node 4
2018-06-01 20:57:35.887 Detail, Node004, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=4): 0x01, 0x05, 0x00, 0x48, 0x04, 0x46, 0xf0
2018-06-01 20:57:35.887 Detail, Notification: ControllerCommand - Starting
2018-06-01 20:57:35.887 Detail, 
2018-06-01 20:57:35.888 Info, Node004, Sending (Command) message (Callback ID=0x46, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=4): 0x01, 0x05, 0x00, 0x48, 0x04, 0x46, 0xf0
2018-06-01 20:57:35.912 Detail, Node004,   Received: 0x01, 0x05, 0x00, 0x48, 0x46, 0x21, 0xd5
2018-06-01 20:57:35.912 Detail, 
2018-06-01 20:57:35.912 Info, Node004, REQUEST_NEIGHBOR_UPDATE_STARTED
2018-06-01 20:57:35.912 Detail, Node033,   Expected callbackId was received
2018-06-01 20:57:35.912 Detail, Node033,   Expected reply was received
2018-06-01 20:57:35.912 Detail, Node033,   Message transaction complete
2018-06-01 20:57:35.912 Detail, 
2018-06-01 20:57:35.913 Detail, Node004, Removing current message
2018-06-01 20:57:35.913 Detail, Notification: ControllerCommand - InProgress
2018-06-01 20:57:35.913 Info, WriteNextMsg Controller nothing to do
2018-06-01 20:57:37.304 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x46, 0x22, 0xd6
2018-06-01 20:57:37.304 Detail, 
2018-06-01 20:57:37.304 Info, REQUEST_NEIGHBOR_UPDATE_DONE
2018-06-01 20:57:37.304 Detail, Requesting routing info (neighbor list) for Node 4
2018-06-01 20:57:37.304 Detail, Node004, Queuing (Command) Get Routing Info (Node=4): 0x01, 0x07, 0x00, 0x80, 0x04, 0x00, 0x00, 0x03, 0x7f
2018-06-01 20:57:37.304 Detail, Notification: ControllerCommand - Completed
2018-06-01 20:57:37.305 Detail, 
2018-06-01 20:57:37.305 Info, Node004, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=4): 0x01, 0x07, 0x00, 0x80, 0x04, 0x00, 0x00, 0x03, 0x7f
2018-06-01 20:57:37.314 Detail, Node004,   Received: 0x01, 0x20, 0x01, 0x80, 0x37, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x69
2018-06-01 20:57:37.314 Detail, 
2018-06-01 20:57:37.314 Info, Node004, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-06-01 20:57:37.314 Info, Node004,     Neighbors of this node are:
2018-06-01 20:57:37.314 Info, Node004,     Node 1
2018-06-01 20:57:37.314 Info, Node004,     Node 2
2018-06-01 20:57:37.314 Info, Node004,     Node 3
2018-06-01 20:57:37.314 Info, Node004,     Node 5
2018-06-01 20:57:37.314 Info, Node004,     Node 6
2018-06-01 20:57:37.314 Detail,   Expected reply was received
2018-06-01 20:57:37.314 Detail,   Message transaction complete
2018-06-01 20:57:37.314 Detail, 
2018-06-01 20:57:37.315 Detail, Node004, Removing current message
2018-06-01 20:57:37.315 Info, Requesting Neighbor Update for node 5
2018-06-01 20:57:37.315 Detail, Node005, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=5): 0x01, 0x05, 0x00, 0x48, 0x05, 0x47, 0xf0
2018-06-01 20:57:37.315 Detail, Notification: ControllerCommand - Starting
2018-06-01 20:57:37.316 Detail, 
2018-06-01 20:57:37.316 Info, Node005, Sending (Command) message (Callback ID=0x47, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=5): 0x01, 0x05, 0x00, 0x48, 0x05, 0x47, 0xf0
2018-06-01 20:57:37.401 Detail, Node005,   Received: 0x01, 0x05, 0x00, 0x48, 0x47, 0x21, 0xd4
2018-06-01 20:57:37.402 Detail, 
2018-06-01 20:57:37.402 Info, Node005, REQUEST_NEIGHBOR_UPDATE_STARTED
2018-06-01 20:57:37.402 Detail, Node033,   Expected callbackId was received
2018-06-01 20:57:37.402 Detail, Node033,   Expected reply was received
2018-06-01 20:57:37.402 Detail, Node033,   Message transaction complete
2018-06-01 20:57:37.402 Detail, 
2018-06-01 20:57:37.402 Detail, Node005, Removing current message
2018-06-01 20:57:37.402 Detail, Notification: ControllerCommand - InProgress
2018-06-01 20:57:37.403 Info, WriteNextMsg Controller nothing to do
2018-06-01 20:57:49.327 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x47, 0x23, 0xd6
2018-06-01 20:57:49.327 Detail, 
2018-06-01 20:57:49.327 Warning, WARNING: REQUEST_NEIGHBOR_UPDATE_FAILED
2018-06-01 20:57:49.327 Detail, Notification: ControllerCommand - Failed
2018-06-01 20:57:49.328 Info, Requesting Neighbor Update for node 6
2018-06-01 20:57:49.328 Detail, Node006, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=6): 0x01, 0x05, 0x00, 0x48, 0x06, 0x48, 0xfc
2018-06-01 20:57:49.328 Detail, Notification: ControllerCommand - Starting
2018-06-01 20:57:49.329 Detail, 
2018-06-01 20:57:49.329 Info, Node006, Sending (Command) message (Callback ID=0x48, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=6): 0x01, 0x05, 0x00, 0x48, 0x06, 0x48, 0xfc
2018-06-01 20:57:49.414 Detail, Node006,   Received: 0x01, 0x05, 0x00, 0x48, 0x48, 0x21, 0xdb
2018-06-01 20:57:49.415 Detail, 
2018-06-01 20:57:49.415 Info, Node006, REQUEST_NEIGHBOR_UPDATE_STARTED
2018-06-01 20:57:49.415 Detail, Node033,   Expected callbackId was received
2018-06-01 20:57:49.415 Detail, Node033,   Expected reply was received
2018-06-01 20:57:49.415 Detail, Node033,   Message transaction complete
2018-06-01 20:57:49.415 Detail, 
2018-06-01 20:57:49.415 Detail, Node006, Removing current message
2018-06-01 20:57:49.415 Detail, Notification: ControllerCommand - InProgress
2018-06-01 20:57:49.416 Info, WriteNextMsg Controller nothing to do
2018-06-01 20:57:51.666 Detail,   Received: 0x01, 0x05, 0x00, 0x48, 0x48, 0x22, 0xd8
2018-06-01 20:57:51.666 Detail, 
2018-06-01 20:57:51.666 Info, REQUEST_NEIGHBOR_UPDATE_DONE
2018-06-01 20:57:51.666 Detail, Requesting routing info (neighbor list) for Node 6
2018-06-01 20:57:51.666 Detail, Node006, Queuing (Command) Get Routing Info (Node=6): 0x01, 0x07, 0x00, 0x80, 0x06, 0x00, 0x00, 0x03, 0x7d
2018-06-01 20:57:51.667 Detail, Notification: ControllerCommand - Completed
2018-06-01 20:57:51.667 Detail, 
2018-06-01 20:57:51.667 Info, Node006, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=6): 0x01, 0x07, 0x00, 0x80, 0x06, 0x00, 0x00, 0x03, 0x7d
2018-06-01 20:57:51.676 Detail, Node006,   Received: 0x01, 0x20, 0x01, 0x80, 0x1e, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x40
2018-06-01 20:57:51.676 Detail, 
2018-06-01 20:57:51.676 Info, Node006, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-06-01 20:57:51.676 Info, Node006,     Neighbors of this node are:
2018-06-01 20:57:51.676 Info, Node006,     Node 2
2018-06-01 20:57:51.676 Info, Node006,     Node 3
2018-06-01 20:57:51.676 Info, Node006,     Node 4
2018-06-01 20:57:51.676 Info, Node006,     Node 5
2018-06-01 20:57:51.676 Detail,   Expected reply was received
2018-06-01 20:57:51.676 Detail,   Message transaction complete
2018-06-01 20:57:51.676 Detail, 
2018-06-01 20:57:51.676 Detail, Node006, Removing current message