Freshly added devices can't be polled / presumed dead with new UZB

netopiax · September 12, 2017, 12:45am

Hi - I’m new to HA and very impressed by the software. Over the past week I got it working on an RP3 using the AIO installer. I’ve been controlling everything in my house via my existing Wink setup. I am moving things to direct HA control so I can retire Wink (I don’t want/need the cloud involved in my home automation, and I want more complex automations, and Wink has mediocre support for many Z-Wave devices.)

I moved ecobee and Hue devices out of Wink and onto HA no problem but all hell has broken loose upon trying to move to a Z-Wave.me UZB device. I have removed a couple devices from the Wink Z-Wave hub, specifically a Jasco dimmer and a jasco plug-in lamp module. But when I add them to the UZB network, they successfully add and then immediately fail to respond to the NoOp probing commands. See relevant logs below.

If I go turn the switch on or off at the physical switch, the controller can see it and more messages will appear in the log (Info_updated) - I’ve seen a Warning, device revived (or something to that effect), followed by more probes that fail immediately. This leads me to believe it is not a range issue as others have experienced. However, I added a USB extension cable just in case. The UZB is 8 feet from the plug-in dimmer and 15-20 feet from the wall dimmer.

I have tried a hard reset on the UZB and also a factory reset on the Jasco dimmer with no success. What else should I be trying?

2017-09-12 00:28:42.380 Detail, Queuing (Controller) Add Device
2017-09-12 00:28:42.382 Info, Add Device
2017-09-12 00:28:42.382 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0b, 0x7a
2017-09-12 00:28:42.383 Detail, Notification: ControllerCommand - Starting
2017-09-12 00:28:42.385 Detail, 
2017-09-12 00:28:42.386 Info, contrlr, Sending (Command) message (Callback ID=0x0b, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0b, 0x7a
2017-09-12 00:28:42.389 Detail, contrlr,   Received: 0x01, 0x07, 0x00, 0x4a, 0x0b, 0x01, 0x00, 0x00, 0xb8
2017-09-12 00:28:42.390 Detail, 
2017-09-12 00:28:42.390 Info, contrlr, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2017-09-12 00:28:42.391 Info, contrlr, ADD_NODE_STATUS_LEARN_READY
2017-09-12 00:28:42.391 Detail, Node001,   Expected callbackId was received
2017-09-12 00:28:42.391 Detail, Node001,   Expected reply was received
2017-09-12 00:28:42.392 Detail, Node001,   Message transaction complete
2017-09-12 00:28:42.392 Detail, 
2017-09-12 00:28:42.392 Detail, contrlr, Removing current message
2017-09-12 00:28:42.393 Detail, Notification: ControllerCommand - Waiting
2017-09-12 00:28:47.703 Detail,   Received: 0x01, 0x18, 0x00, 0x4a, 0x0b, 0x02, 0x02, 0x11, 0x04, 0x11, 0x01, 0x5e, 0x56, 0x86, 0x72, 0x5a, 0x85, 0x59, 0x73, 0x26, 0x27, 0x70, 0x2c, 0x2b, 0x7a, 0xa6
2017-09-12 00:28:47.703 Detail, 
2017-09-12 00:28:47.703 Info, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2017-09-12 00:28:47.703 Info, ADD_NODE_STATUS_NODE_FOUND
2017-09-12 00:28:47.704 Detail, Notification: ControllerCommand - InProgress
2017-09-12 00:28:47.707 Detail,   Received: 0x01, 0x18, 0x00, 0x4a, 0x0b, 0x03, 0x02, 0x11, 0x04, 0x11, 0x01, 0x5e, 0x56, 0x86, 0x72, 0x5a, 0x85, 0x59, 0x73, 0x26, 0x27, 0x70, 0x2c, 0x2b, 0x7a, 0xa7
2017-09-12 00:28:47.707 Detail, 
2017-09-12 00:28:47.707 Info, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2017-09-12 00:28:47.707 Info, ADD_NODE_STATUS_ADDING_SLAVE
2017-09-12 00:28:47.707 Info, Adding node ID 2 - Secure
2017-09-12 00:28:47.707 Detail, Notification: ControllerCommand - InProgress
2017-09-12 00:28:55.383 Detail,   Received: 0x01, 0x07, 0x00, 0x4a, 0x0b, 0x05, 0x02, 0x00, 0xbe
2017-09-12 00:28:55.384 Detail, 
2017-09-12 00:28:55.384 Info, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2017-09-12 00:28:55.384 Info, ADD_NODE_STATUS_PROTOCOL_DONE
2017-09-12 00:28:55.384 Detail, contrlr, Queuing (Command) Add Node Stop: 0x01, 0x04, 0x00, 0x4a, 0x05, 0xb4
2017-09-12 00:28:55.385 Detail, Notification: ControllerCommand - InProgress
2017-09-12 00:28:55.385 Detail, 
2017-09-12 00:28:55.385 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x4a) - Add Node Stop: 0x01, 0x04, 0x00, 0x4a, 0x05, 0xb4
2017-09-12 00:28:55.537 Detail, contrlr,   Received: 0x01, 0x07, 0x00, 0x4a, 0x0b, 0x06, 0x02, 0x00, 0xbd
2017-09-12 00:28:55.538 Detail, 
2017-09-12 00:28:55.538 Info, contrlr, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2017-09-12 00:28:55.538 Info, contrlr, ADD_NODE_STATUS_DONE
2017-09-12 00:28:55.544 Info, Node002,   Basic device class    (0x04) - Routing Slave
2017-09-12 00:28:55.545 Info, Node002,   Generic device Class  (0x11) - Multilevel Switch
2017-09-12 00:28:55.545 Info, Node002,   Specific device class (0x01) - Multilevel Power Switch
2017-09-12 00:28:55.545 Info, Node002,     COMMAND_CLASS_BASIC will be mapped to COMMAND_CLASS_SWITCH_MULTILEVEL
2017-09-12 00:28:55.545 Info, Node002,   Mandatory Command Classes for Node 2:
2017-09-12 00:28:55.545 Info, Node002,     COMMAND_CLASS_BASIC
2017-09-12 00:28:55.545 Info, Node002,     COMMAND_CLASS_SWITCH_MULTILEVEL
2017-09-12 00:28:55.545 Info, Node002,     COMMAND_CLASS_SWITCH_ALL
2017-09-12 00:28:55.546 Info, Node002,   Mandatory Command Classes controlled by Node 2:
2017-09-12 00:28:55.546 Info, Node002,     None
2017-09-12 00:28:55.546 Info, Node002,   Optional command classes for node 2:
2017-09-12 00:28:55.546 Info, Node002,     COMMAND_CLASS_ZWAVE_PLUS_INFO
2017-09-12 00:28:55.546 Info, Node002,     COMMAND_CLASS_CRC_16_ENCAP
2017-09-12 00:28:55.546 Info, Node002,     COMMAND_CLASS_VERSION
2017-09-12 00:28:55.546 Info, Node002,     COMMAND_CLASS_MANUFACTURER_SPECIFIC
2017-09-12 00:28:55.546 Info, Node002,     COMMAND_CLASS_DEVICE_RESET_LOCALLY
2017-09-12 00:28:55.547 Info, Node002,     COMMAND_CLASS_ASSOCIATION
2017-09-12 00:28:55.547 Info, Node002,   CommandClass 0x59 - NOT REQUIRED
2017-09-12 00:28:55.547 Info, Node002,     COMMAND_CLASS_POWERLEVEL
2017-09-12 00:28:55.547 Info, Node002,     COMMAND_CLASS_SWITCH_MULTILEVEL (Existing)
2017-09-12 00:28:55.547 Info, Node002,     COMMAND_CLASS_SWITCH_ALL (Existing)
2017-09-12 00:28:55.547 Info, Node002,     COMMAND_CLASS_CONFIGURATION
2017-09-12 00:28:55.547 Info, Node002,   CommandClass 0x2c - NOT REQUIRED
2017-09-12 00:28:55.548 Info, Node002,     COMMAND_CLASS_SCENE_ACTIVATION
2017-09-12 00:28:55.548 Info, Node002,   CommandClass 0x7a - NOT REQUIRED
2017-09-12 00:28:55.548 Detail, Node002, AdvanceQueries queryPending=0 queryRetries=0 queryStage=None live=1
2017-09-12 00:28:55.548 Detail, Node002, QueryStage_ProtocolInfo
2017-09-12 00:28:55.548 Detail, Node002, Queuing (Query) Get Node Protocol Info (Node=2): 0x01, 0x04, 0x00, 0x41, 0x02, 0xb8
2017-09-12 00:28:55.548 Detail, Node002, Queuing (Query) Query Stage Complete (ProtocolInfo)
2017-09-12 00:28:55.549 Info, Node002, Initializing Node. New Node: true (true)
2017-09-12 00:28:55.549 Detail, Node006,   Expected reply was received
2017-09-12 00:28:55.549 Detail, Node006,   Message transaction complete
2017-09-12 00:28:55.549 Detail, 
2017-09-12 00:28:55.549 Detail, contrlr, Removing current message
2017-09-12 00:28:55.549 Detail, Node002, Notification: NodeAdded
2017-09-12 00:28:55.560 Detail, Node002, Notification: NodeProtocolInfo
2017-09-12 00:28:55.562 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.565 Info, Node002, DisablePoll failed - value not on list
2017-09-12 00:28:55.571 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.574 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.578 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.583 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.587 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.590 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.592 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.596 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.602 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.606 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.610 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.613 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.615 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.617 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.618 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.620 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.621 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.623 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.625 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.626 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.628 Detail, Node002, Notification: ValueAdded
2017-09-12 00:28:55.630 Detail, Notification: ControllerCommand - Completed
2017-09-12 00:28:55.630 Detail, 
2017-09-12 00:28:55.631 Info, Node002, Sending (Query) message (Callback ID=0x00, Expected Reply=0x41) - Get Node Protocol Info (Node=2): 0x01, 0x04, 0x00, 0x41, 0x02, 0xb8
2017-09-12 00:28:55.633 Detail, Node002,   Received: 0x01, 0x09, 0x01, 0x41, 0xd3, 0x9c, 0x01, 0x04, 0x11, 0x01, 0xec
2017-09-12 00:28:55.633 Detail, 
2017-09-12 00:28:55.633 Info, Node002, Received reply to FUNC_ID_ZW_GET_NODE_PROTOCOL_INFO
2017-09-12 00:28:55.633 Info, Node002,   Protocol Info for Node 2:
2017-09-12 00:28:55.633 Info, Node002,     Listening     = true
2017-09-12 00:28:55.633 Info, Node002,     Beaming       = true
2017-09-12 00:28:55.634 Info, Node002,     Routing       = true
2017-09-12 00:28:55.634 Info, Node002,     Max Baud Rate = 40000
2017-09-12 00:28:55.634 Info, Node002,     Version       = 4
2017-09-12 00:28:55.634 Info, Node002,     Security      = false
2017-09-12 00:28:55.634 Detail, Node156,   Expected reply was received
2017-09-12 00:28:55.634 Detail, Node156,   Message transaction complete
2017-09-12 00:28:55.634 Detail, 
2017-09-12 00:28:55.634 Detail, Node002, Removing current message
2017-09-12 00:28:55.634 Detail, Node002, Query Stage Complete (ProtocolInfo)
2017-09-12 00:28:55.634 Detail, Node002, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Probe live=1
2017-09-12 00:28:55.635 Detail, Node002, QueryStage_Probe
2017-09-12 00:28:55.635 Info, Node002, NoOperation::Set - Routing=true
2017-09-12 00:28:55.635 Detail, Node002, Queuing (NoOp) NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xcc
2017-09-12 00:28:55.635 Detail, Node002, Queuing (Query) Query Stage Complete (Probe)
2017-09-12 00:28:55.635 Detail, 
2017-09-12 00:28:55.635 Info, Node002, Sending (NoOp) message (Callback ID=0x0c, Expected Reply=0x13) - NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xcc
2017-09-12 00:28:55.647 Detail, Node002,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-09-12 00:28:55.647 Detail, Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2017-09-12 00:28:59.776 Detail, Node002,   Received: 0x01, 0x07, 0x00, 0x13, 0x0c, 0x01, 0x01, 0x9d, 0x7a
2017-09-12 00:28:59.777 Detail, Node002,   ZW_SEND_DATA Request with callback ID 0x0c received (expected 0x0c)
2017-09-12 00:28:59.777 Info, Node002, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2017-09-12 00:28:59.777 Warning, Node002, WARNING: Device is not a sleeping node.
2017-09-12 00:28:59.778 Info, Node002, QueryStageRetry stage Probe requested stage Probe max 3 retries 0 pending 1
2017-09-12 00:28:59.778 Detail, Node001,   Expected callbackId was received
2017-09-12 00:28:59.778 Detail, Node001,   Expected reply was received
2017-09-12 00:28:59.779 Detail, Node001,   Message transaction complete
2017-09-12 00:28:59.779 Detail, 
2017-09-12 00:28:59.779 Detail, Node002, Removing current message
2017-09-12 00:28:59.780 Detail, Node002, Notification: Notification - NoOperation
2017-09-12 00:28:59.784 Detail, Node002, Query Stage Complete (Probe)
2017-09-12 00:28:59.784 Detail, Node002, AdvanceQueries queryPending=0 queryRetries=1 queryStage=Probe live=1
2017-09-12 00:28:59.784 Detail, Node002, QueryStage_Probe
2017-09-12 00:28:59.785 Info, Node002, NoOperation::Set - Routing=true
2017-09-12 00:28:59.785 Detail, Node002, Queuing (NoOp) NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0d, 0xcd
2017-09-12 00:28:59.785 Detail, Node002, Queuing (Query) Query Stage Complete (Probe)
2017-09-12 00:28:59.786 Detail, 
2017-09-12 00:28:59.786 Info, Node002, Sending (NoOp) message (Callback ID=0x0d, Expected Reply=0x13) - NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0d, 0xcd
2017-09-12 00:28:59.799 Detail, Node002,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-09-12 00:28:59.799 Detail, Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2017-09-12 00:29:03.957 Detail, Node002,   Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x01, 0x01, 0xa0, 0x46
2017-09-12 00:29:03.957 Detail, Node002,   ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d)
2017-09-12 00:29:03.958 Info, Node002, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2017-09-12 00:29:03.958 Warning, Node002, WARNING: Device is not a sleeping node.
2017-09-12 00:29:03.958 Info, Node002, QueryStageRetry stage Probe requested stage Probe max 3 retries 1 pending 1
2017-09-12 00:29:03.959 Detail, Node001,   Expected callbackId was received
2017-09-12 00:29:03.959 Detail, Node001,   Expected reply was received
2017-09-12 00:29:03.959 Detail, Node001,   Message transaction complete
2017-09-12 00:29:03.960 Detail, 
2017-09-12 00:29:03.960 Detail, Node002, Removing current message
2017-09-12 00:29:03.960 Detail, Node002, Notification: Notification - NoOperation
2017-09-12 00:29:03.964 Detail, Node002, Query Stage Complete (Probe)
2017-09-12 00:29:03.965 Detail, Node002, AdvanceQueries queryPending=0 queryRetries=2 queryStage=Probe live=1
2017-09-12 00:29:03.965 Detail, Node002, QueryStage_Probe
2017-09-12 00:29:03.965 Info, Node002, NoOperation::Set - Routing=true
2017-09-12 00:29:03.966 Detail, Node002, Queuing (NoOp) NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0e, 0xce
2017-09-12 00:29:03.966 Detail, Node002, Queuing (Query) Query Stage Complete (Probe)
2017-09-12 00:29:03.966 Detail, 
2017-09-12 00:29:03.967 Info, Node002, Sending (NoOp) message (Callback ID=0x0e, Expected Reply=0x13) - NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0e, 0xce
2017-09-12 00:29:03.979 Detail, Node002,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-09-12 00:29:03.980 Detail, Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2017-09-12 00:29:08.076 Detail, Node002,   Received: 0x01, 0x07, 0x00, 0x13, 0x0e, 0x01, 0x01, 0x9a, 0x7f
2017-09-12 00:29:08.077 Detail, Node002,   ZW_SEND_DATA Request with callback ID 0x0e received (expected 0x0e)
2017-09-12 00:29:08.077 Info, Node002, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2017-09-12 00:29:08.077 Warning, Node002, WARNING: Device is not a sleeping node.
2017-09-12 00:29:08.078 Error, Node002, ERROR: node presumed dead
2017-09-12 00:29:08.078 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2017-09-12 00:29:08.078 Info, Node002, QueryStageRetry stage Probe requested stage Probe max 3 retries 2 pending 1
2017-09-12 00:29:08.079 Detail, Node001,   Expected callbackId was received
2017-09-12 00:29:08.079 Detail, Node001,   Expected reply was received
2017-09-12 00:29:08.079 Detail, Node001,   Message transaction complete
2017-09-12 00:29:08.080 Detail, 
2017-09-12 00:29:08.080 Detail, Node002, Removing current message
2017-09-12 00:29:08.080 Detail, Node002, Notification: Notification - NoOperation
2017-09-12 00:29:08.084 Detail, Node002, Notification: Notification - Node Dead
2017-09-12 00:29:08.088 Detail, Node002, Query Stage Complete (Probe)
2017-09-12 00:29:08.088 Detail, Node002, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Probe live=0

hotswapster · October 7, 2017, 11:22am

Hey,
I have the same issue but using Aeotec Smart Switch 6 devices. I setup my wave network a few months ago. Have updated HASS since then and all existing devices work. New device pairs and then becomes “presumed dead”.

I see that if you add a network key to the config it has fixed it for some people, but this has not worked for me. I’m at the point now I’m going to factory reset all the wave devices and see how I go…unless there is anyone else with an idea?

The log says the controller doesn’t receive an ACK and then “presumes dead”.

netopiax · October 7, 2017, 4:25pm

In the name of troubleshooting I compiled OZWCP on my Mac laptop and carried it around the house to see if anything would join the network. It wouldn’t, and I concluded the Z-Wave.me UZB was faulty. (It also had a house ID of 0x55555555 which perhaps should have been a red flag to begin with!) I sent it back and got an Aeotec Z-Stick which worked perfectly with zero other changes to my configuration. My Z-Wave network has been healthy since, though getting manufacturer specific settings to load has been another challenge.