Zwave stuck initializing (wakeup)

coldasijs · April 29, 2018, 2:15pm

Hi all,

I’m a complete noob with Home assistant and Z-Wave. I started yesterday with setting up hass.io on a RPi3 and the Razberry board. My plan was to connect all my Fibaro FGSD002 smoke detectors and a CO detector to Home assistant. I setup Z-wave according to the manual on this site. I added all my sensors to the network. This morning all the sensors were still in the initializing (wakeup) state. So I decided to wake them up manually. I repeated this multiple times and with different detectors. If I push the button on the smoke detector I see in the node info is_awake change from false to true. This takes ~4 secs and then it changes back to false. I removed all nodes, did a reboot of HA and added 1 node again. This afternoon I decided to install hassbian, just to see if the issue is in hassio. However this is gives the same result.

Things I tried so far:

Multiple reboots of home assistant
Manually waking up the sensors multiple times (5-10x)
Removing all the sensors and adding them again
Install Haspbian (started with hass.io)
Googled for similar cases, cannot find any where Z-wave gets stuck on

Am I missing something and should I have more patience?
Or is something wrong in my setup?
Any help would be appreciated.

Here is my OZW log. Based on the logging I cannot see any obvious issues.
Steps I took during this log is: Restart HA, added a new node, manually start node a couple of times.

2018-04-29 11:41:12.847 Always, OpenZwave Version 1.4.2926 Starting Up
2018-04-29 11:41:13.840 Info, Setting Up Provided Network Key for Secure Communications
2018-04-29 11:41:13.841 Warning, Failed - Network Key Not Set
2018-04-29 11:41:13.841 Info, mgr, Added driver for controller /dev/ttyAMA0
2018-04-29 11:41:13.841 Info, Opening controller /dev/ttyAMA0
2018-04-29 11:41:13.841 Info, Trying to open serial port /dev/ttyAMA0 (attempt 1)
2018-04-29 11:41:13.841 Info, Serial port /dev/ttyAMA0 opened (attempt 1)
2018-04-29 11:41:13.842 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-04-29 11:41:13.842 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-04-29 11:41:13.842 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-04-29 11:41:13.842 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-04-29 11:41:13.842 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-04-29 11:41:13.842 Detail,
2018-04-29 11:41:13.842 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2018-04-29 11:41:13.845 Detail, contrlr, Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x30, 0x35, 0x00, 0x01, 0x97
2018-04-29 11:41:13.845 Detail,
2018-04-29 11:41:13.845 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2018-04-29 11:41:13.845 Info, contrlr, Static Controller library, version Z-Wave 4.05
2018-04-29 11:41:13.845 Detail, Node045, Expected reply was received
2018-04-29 11:41:13.845 Detail, Node045, Message transaction complete
2018-04-29 11:41:13.845 Detail,
2018-04-29 11:41:13.845 Detail, contrlr, Removing current message
2018-04-29 11:41:13.845 Detail,
2018-04-29 11:41:13.845 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2018-04-29 11:41:13.848 Detail, contrlr, Received: 0x01, 0x08, 0x01, 0x20, 0x55, 0x55, 0x55, 0x55, 0x01, 0xd7
2018-04-29 11:41:13.848 Detail,
2018-04-29 11:41:13.848 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0x55555555. Our node ID = 1
2018-04-29 11:41:13.848 Detail, Node085, Expected reply was received
2018-04-29 11:41:13.848 Detail, Node085, Message transaction complete
2018-04-29 11:41:13.848 Detail,
2018-04-29 11:41:13.848 Detail, contrlr, Removing current message
2018-04-29 11:41:13.848 Detail,
2018-04-29 11:41:13.848 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2018-04-29 11:41:13.850 Detail, contrlr, Received: 0x01, 0x04, 0x01, 0x05, 0x20, 0xdf
2018-04-29 11:41:13.853 Detail,
2018-04-29 11:41:13.853 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2018-04-29 11:41:13.853 Info, contrlr, There is no SUC ID Server (SIS) in this network.
2018-04-29 11:41:13.853 Info, contrlr, The PC controller is a primary controller.
2018-04-29 11:41:13.853 Detail, Node223, Expected reply was received
2018-04-29 11:41:13.854 Detail, Node223, Message transaction complete
2018-04-29 11:41:13.854 Detail,
2018-04-29 11:41:13.854 Detail, contrlr, Removing current message
2018-04-29 11:41:13.854 Detail,
2018-04-29 11:41:13.854 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2018-04-29 11:41:13.859 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-04-29 11:41:13.859 Detail,
2018-04-29 11:41:13.859 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2018-04-29 11:41:13.859 Info, contrlr, Serial API Version: 5.4
2018-04-29 11:41:13.859 Info, contrlr, Manufacturer ID: 0x0147
2018-04-29 11:41:13.859 Info, contrlr, Product Type: 0x0400
2018-04-29 11:41:13.860 Info, contrlr, Product ID: 0x0002
2018-04-29 11:41:13.860 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2018-04-29 11:41:13.860 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2018-04-29 11:41:13.860 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2018-04-29 11:41:13.860 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2018-04-29 11:41:13.860 Detail, Node004, Expected reply was received
2018-04-29 11:41:13.860 Detail, Node004, Message transaction complete
2018-04-29 11:41:13.860 Detail,
2018-04-29 11:41:13.860 Detail, contrlr, Removing current message
2018-04-29 11:41:13.860 Detail,
2018-04-29 11:41:13.860 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2018-04-29 11:41:13.862 Detail, contrlr, Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2018-04-29 11:41:13.862 Detail,
2018-04-29 11:41:13.862 Info, contrlr, Received reply to GET_SUC_NODE_ID. Node ID = 0
2018-04-29 11:41:13.862 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node
2018-04-29 11:41:13.862 Detail, Node172, Expected reply was received
2018-04-29 11:41:13.862 Detail, Node172, Message transaction complete
2018-04-29 11:41:13.862 Detail,
2018-04-29 11:41:13.862 Detail, contrlr, Removing current message
2018-04-29 11:41:13.863 Detail,
2018-04-29 11:41:13.863 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2018-04-29 11:41:13.916 Detail, contrlr, Received: 0x01, 0x25, 0x01, 0x1c, 0x01, 0x20, 0xdb, 0xdc, 0x60, 0xb5, 0xb6, 0x5d, 0x71, 0x5f, 0x1e, 0x95, 0xa1, 0xa7, 0x4f, 0xdd, 0xa1, 0xd9, 0x13, 0x8e, 0x0e, 0x44, 0x61, 0x66, 0x40, 0x44, 0xa3, 0x8b, 0x20, 0xf1, 0x0a, 0xa1, 0xc9, 0xa2, 0x7b
2018-04-29 11:41:13.917 Detail,
2018-04-29 11:41:13.917 Info, contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2018-04-29 11:41:13.917 Detail, Node032, Expected reply was received
2018-04-29 11:41:13.917 Detail, Node032, Message transaction complete
2018-04-29 11:41:13.917 Detail,
2018-04-29 11:41:13.917 Detail, contrlr, Removing current message
2018-04-29 11:41:13.917 Detail,
2018-04-29 11:41:13.917 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x02) - FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2018-04-29 11:41:13.976 Detail, contrlr, Received: 0x01, 0x25, 0x01, 0x02, 0x05, 0x00, 0x1d, 0x01, 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, 0xc5
2018-04-29 11:41:13.976 Detail,
2018-04-29 11:41:13.976 Info, mgr, Driver with Home ID of 0x55555555 is now ready.
2018-04-29 11:41:13.976 Info,
2018-04-29 11:41:13.977 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2018-04-29 11:41:13.977 Info, contrlr, Node 001 - Known
2018-04-29 11:41:13.977 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2018-04-29 11:41:13.977 Detail, Node001, QueryStage_CacheLoad
2018-04-29 11:41:13.977 Info, Node001, Node Identity Codes: 0147:0400:0002
2018-04-29 11:41:13.977 Detail, Node001, QueryStage_Associations
2018-04-29 11:41:13.977 Detail, Node001, QueryStage_Neighbors
2018-04-29 11:41:13.977 Detail, contrlr, Requesting routing info (neighbor list) for Node 1
2018-04-29 11:41:13.977 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2018-04-29 11:41:13.977 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2018-04-29 11:41:13.977 Detail, Expected reply was received
2018-04-29 11:41:13.977 Detail, Message transaction complete
2018-04-29 11:41:13.977 Detail,
2018-04-29 11:41:13.977 Detail, contrlr, Removing current message
2018-04-29 11:41:13.977 Detail, Node001, Notification: DriverReady
2018-04-29 11:41:14.003 Detail, Node001, Notification: NodeAdded
2018-04-29 11:41:15.474 Detail, Node001, Notification: NodeProtocolInfo
2018-04-29 11:41:15.507 Detail, Node001, Notification: EssentialNodeQueriesComplete
2018-04-29 11:41:15.527 Detail, Node001, Notification: ValueAdded
2018-04-29 11:41:15.547 Detail, Node001, Notification: NodeNaming
2018-04-29 11:41:15.554 Detail,
2018-04-29 11:41:15.554 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-04-29 11:41:15.556 Detail, contrlr, Received: 0x01, 0x05, 0x01, 0x06, 0x64, 0x0f, 0x96
2018-04-29 11:41:15.556 Detail,
2018-04-29 11:41:15.556 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_SET_TIMEOUTS
2018-04-29 11:41:15.556 Detail, Node015, Expected reply was received
2018-04-29 11:41:15.556 Detail, Node015, Message transaction complete
2018-04-29 11:41:15.556 Detail,
2018-04-29 11:41:15.556 Detail, contrlr, Removing current message
2018-04-29 11:41:15.556 Detail,
2018-04-29 11:41:15.556 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-04-29 11:41:15.557 Detail, contrlr, Removing current message
2018-04-29 11:41:15.557 Detail,
2018-04-29 11:41:15.557 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-04-29 11:41:15.563 Detail, Node001, Received: 0x01, 0x20, 0x01, 0x80, 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, 0x00, 0x5e
2018-04-29 11:41:15.563 Detail,
2018-04-29 11:41:15.563 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2018-04-29 11:41:15.563 Info, Node001, Neighbors of this node are:
2018-04-29 11:41:15.563 Info, Node001, (none reported)
2018-04-29 11:41:15.563 Detail, Expected reply was received
2018-04-29 11:41:15.563 Detail, Message transaction complete
2018-04-29 11:41:15.563 Detail,
2018-04-29 11:41:15.563 Detail, Node001, Removing current message
2018-04-29 11:41:15.563 Detail, Node001, Query Stage Complete (Neighbors)
2018-04-29 11:41:15.563 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2018-04-29 11:41:15.563 Detail, Node001, QueryStage_Session
2018-04-29 11:41:15.563 Detail, Node001, QueryStage_Dynamic
2018-04-29 11:41:15.563 Detail, Node001, QueryStage_Configuration
2018-04-29 11:41:15.563 Detail, Node001, QueryStage_Complete
2018-04-29 11:41:15.563 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2018-04-29 11:41:15.563 Warning, CheckCompletedNodeQueries all=1, deadFound=0 sleepingOnly=1
2018-04-29 11:41:15.563 Info, Node query processing complete.
2018-04-29 11:41:15.564 Detail, Node001, Notification: NodeQueriesComplete
2018-04-29 11:41:15.576 Detail, contrlr, Notification: AllNodesQueried
2018-04-29 11:42:12.086 Detail, Node001, Queuing (Controller) Request Node Neighbor Update
2018-04-29 11:42:12.087 Info, Requesting Neighbor Update for node 1
2018-04-29 11:42:12.087 Detail, Node001, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0a, 0xb9
2018-04-29 11:42:12.087 Detail, Notification: ControllerCommand - Starting
2018-04-29 11:42:12.088 Detail,
2018-04-29 11:42:12.088 Info, Node001, Sending (Command) message (Callback ID=0x0a, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0a, 0xb9
2018-04-29 11:42:12.102 Detail, Node001, Received: 0x01, 0x05, 0x00, 0x48, 0x0a, 0x23, 0x9b
2018-04-29 11:42:12.102 Detail,
2018-04-29 11:42:12.102 Warning, Node001, WARNING: REQUEST_NEIGHBOR_UPDATE_FAILED
2018-04-29 11:42:12.102 Detail, Node035, Expected callbackId was received
2018-04-29 11:42:12.102 Detail, Node035, Expected reply was received
2018-04-29 11:42:12.102 Detail, Node035, Message transaction complete
2018-04-29 11:42:12.102 Detail,
2018-04-29 11:42:12.103 Detail, Node001, Removing current message
2018-04-29 11:42:12.105 Detail, Notification: ControllerCommand - Failed
2018-04-29 11:42:32.139 Detail, Queuing (Controller) Add Device
2018-04-29 11:42:32.140 Info, Add Device
2018-04-29 11:42:32.140 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0b, 0x7a
2018-04-29 11:42:32.140 Detail, Notification: ControllerCommand - Starting
2018-04-29 11:42:32.141 Detail,
2018-04-29 11:42:32.141 Info, contrlr, Sending (Command) message (Callback ID=0x0b, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0b, 0x7a
2018-04-29 11:42:32.144 Detail, contrlr, Received: 0x01, 0x07, 0x00, 0x4a, 0x0b, 0x01, 0x00, 0x00, 0xb8
2018-04-29 11:42:32.144 Detail,
2018-04-29 11:42:32.145 Info, contrlr, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2018-04-29 11:42:32.145 Info, contrlr, ADD_NODE_STATUS_LEARN_READY
2018-04-29 11:42:32.145 Detail, Node001, Expected callbackId was received
2018-04-29 11:42:32.145 Detail, Node001, Expected reply was received
2018-04-29 11:42:32.145 Detail, Node001, Message transaction complete
2018-04-29 11:42:32.145 Detail,
2018-04-29 11:42:32.145 Detail, contrlr, Removing current message
2018-04-29 11:42:32.145 Detail, Notification: ControllerCommand - Waiting
2018-04-29 11:42:32.147 Info, WriteNextMsg Controller nothing to do
2018-04-29 11:42:36.403 Detail, Received: 0x01, 0x1d, 0x00, 0x4a, 0x0b, 0x02, 0x04, 0x16, 0x04, 0x07, 0x01, 0x5e, 0x20, 0x86, 0x72, 0x5a, 0x59, 0x85, 0x73, 0x84, 0x80, 0x71, 0x56, 0x70, 0x31, 0x8e, 0x22, 0x9c, 0x98, 0x7a, 0x7e
2018-04-29 11:42:36.403 Detail,
2018-04-29 11:42:36.403 Info, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2018-04-29 11:42:36.403 Info, ADD_NODE_STATUS_NODE_FOUND
2018-04-29 11:42:36.403 Detail, Notification: ControllerCommand - InProgress
2018-04-29 11:42:36.407 Detail, Received: 0x01, 0x1d, 0x00, 0x4a, 0x0b, 0x03, 0x04, 0x16, 0x04, 0x07, 0x01, 0x5e, 0x20, 0x86, 0x72, 0x5a, 0x59, 0x85, 0x73, 0x84, 0x80, 0x71, 0x56, 0x70, 0x31, 0x8e, 0x22, 0x9c, 0x98, 0x7a, 0x7f
2018-04-29 11:42:36.407 Detail,
2018-04-29 11:42:36.407 Info, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2018-04-29 11:42:36.407 Info, ADD_NODE_STATUS_ADDING_SLAVE
2018-04-29 11:42:36.407 Info, Adding node ID 4 - Non-Secure
2018-04-29 11:42:36.407 Detail, Notification: ControllerCommand - InProgress
2018-04-29 11:42:44.111 Detail, Received: 0x01, 0x07, 0x00, 0x4a, 0x0b, 0x05, 0x04, 0x00, 0xb8
2018-04-29 11:42:44.111 Detail,
2018-04-29 11:42:44.112 Info, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2018-04-29 11:42:44.112 Info, ADD_NODE_STATUS_PROTOCOL_DONE
2018-04-29 11:42:44.112 Detail, contrlr, Queuing (Command) Add Node Stop: 0x01, 0x04, 0x00, 0x4a, 0x05, 0xb4
2018-04-29 11:42:44.112 Detail, Notification: ControllerCommand - InProgress
2018-04-29 11:42:44.113 Detail,
2018-04-29 11:42:44.113 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x4a) - Add Node Stop: 0x01, 0x04, 0x00, 0x4a, 0x05, 0xb4
2018-04-29 11:42:44.222 Detail, contrlr, Received: 0x01, 0x07, 0x00, 0x4a, 0x0b, 0x06, 0x04, 0x00, 0xbb
2018-04-29 11:42:44.222 Detail,
2018-04-29 11:42:44.222 Info, contrlr, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2018-04-29 11:42:44.222 Info, contrlr, ADD_NODE_STATUS_DONE
2018-04-29 11:42:44.222 Info, Node004, Network Key Not Set - Secure Option is not required
2018-04-29 11:42:44.233 Info, Node004, Basic device class (0x04) - Routing Slave
2018-04-29 11:42:44.233 Info, Node004, Generic device Class (0x07) - Notification Sensor
2018-04-29 11:42:44.233 Info, Node004, Specific device class (0x01) - Notification Sensor
2018-04-29 11:42:44.233 Info, Node004, COMMAND_CLASS_BASIC is not mapped
2018-04-29 11:42:44.233 Info, Node004, Mandatory Command Classes for Node 4:
2018-04-29 11:42:44.233 Info, Node004, COMMAND_CLASS_BASIC
2018-04-29 11:42:44.234 Info, Node004, Mandatory Command Classes controlled by Node 4:
2018-04-29 11:42:44.234 Info, Node004, None
2018-04-29 11:42:44.234 Info, Node004, Optional command classes for node 4:
2018-04-29 11:42:44.234 Info, Node004, COMMAND_CLASS_ZWAVE_PLUS_INFO
2018-04-29 11:42:44.234 Info, Node004, COMMAND_CLASS_BASIC (Existing)
2018-04-29 11:42:44.234 Info, Node004, COMMAND_CLASS_VERSION
2018-04-29 11:42:44.234 Info, Node004, COMMAND_CLASS_MANUFACTURER_SPECIFIC
2018-04-29 11:42:44.234 Info, Node004, COMMAND_CLASS_DEVICE_RESET_LOCALLY
2018-04-29 11:42:44.234 Info, Node004, CommandClass 0x59 - NOT REQUIRED
2018-04-29 11:42:44.234 Info, Node004, COMMAND_CLASS_ASSOCIATION
2018-04-29 11:42:44.234 Info, Node004, COMMAND_CLASS_POWERLEVEL
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_WAKE_UP
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_BATTERY
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_ALARM
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_CRC_16_ENCAP
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_CONFIGURATION
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_SENSOR_MULTILEVEL
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_APPLICATION_STATUS
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_SENSOR_ALARM
2018-04-29 11:42:44.235 Info, Node004, COMMAND_CLASS_SECURITY (Disabled - Network Key Not Set)
2018-04-29 11:42:44.235 Info, Node004, CommandClass 0x7a - NOT REQUIRED
2018-04-29 11:42:44.235 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=None live=1
2018-04-29 11:42:44.236 Detail, Node004, QueryStage_ProtocolInfo
2018-04-29 11:42:44.236 Detail, Node004, Queuing (Query) Get Node Protocol Info (Node=4): 0x01, 0x04, 0x00, 0x41, 0x04, 0xbe
2018-04-29 11:42:44.236 Detail, Node004, Queuing (Query) Query Stage Complete (ProtocolInfo)
2018-04-29 11:42:44.236 Info, Node004, Initializing Node. New Node: true (true)
2018-04-29 11:42:44.236 Detail, Node006, Expected reply was received
2018-04-29 11:42:44.236 Detail, Node006, Message transaction complete
2018-04-29 11:42:44.236 Detail,
2018-04-29 11:42:44.236 Detail, contrlr, Removing current message
2018-04-29 11:42:44.236 Detail, Node004, Notification: NodeAdded
2018-04-29 11:42:44.272 Detail, Node004, Notification: NodeProtocolInfo
2018-04-29 11:42:44.274 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.276 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.278 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.279 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.281 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.283 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.286 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.288 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.290 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.294 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.297 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.299 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.305 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.307 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.308 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.310 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.313 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.316 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.317 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.318 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.337 Detail, Node004, Notification: ValueAdded
2018-04-29 11:42:44.343 Detail, Notification: ControllerCommand - Completed
2018-04-29 11:42:44.345 Detail,
2018-04-29 11:42:44.345 Info, Node004, Sending (Query) message (Callback ID=0x00, Expected Reply=0x41) - Get Node Protocol Info (Node=4): 0x01, 0x04, 0x00, 0x41, 0x04, 0xbe
2018-04-29 11:42:44.348 Detail, Node004, Received: 0x01, 0x09, 0x01, 0x41, 0x53, 0x9c, 0x01, 0x04, 0x07, 0x01, 0x7a
2018-04-29 11:42:44.348 Detail,
2018-04-29 11:42:44.348 Info, Node004, Received reply to FUNC_ID_ZW_GET_NODE_PROTOCOL_INFO
2018-04-29 11:42:44.348 Info, Node004, Protocol Info for Node 4:
2018-04-29 11:42:44.348 Info, Node004, Listening = false
2018-04-29 11:42:44.348 Info, Node004, Frequent = false
2018-04-29 11:42:44.348 Info, Node004, Beaming = true
2018-04-29 11:42:44.348 Info, Node004, Routing = true
2018-04-29 11:42:44.348 Info, Node004, Max Baud Rate = 40000
2018-04-29 11:42:44.348 Info, Node004, Version = 4
2018-04-29 11:42:44.348 Info, Node004, Security = false
2018-04-29 11:42:44.349 Detail, Node156, Expected reply was received
2018-04-29 11:42:44.349 Detail, Node156, Message transaction complete
2018-04-29 11:42:44.349 Detail,
2018-04-29 11:42:44.349 Detail, Node004, Removing current message
2018-04-29 11:42:44.349 Detail, Node004, Query Stage Complete (ProtocolInfo)
2018-04-29 11:42:44.349 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Probe live=1
2018-04-29 11:42:44.349 Detail, Node004, QueryStage_Probe
2018-04-29 11:42:44.349 Info, Node004, NoOperation::Set - Routing=true
2018-04-29 11:42:44.349 Detail, Node004, Queuing (NoOp) NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xca
2018-04-29 11:42:44.349 Detail, Node004, Queuing (Query) Query Stage Complete (Probe)
2018-04-29 11:42:44.349 Detail,
2018-04-29 11:42:44.349 Info, Node004, Sending (NoOp) message (Callback ID=0x0c, Expected Reply=0x13) - NoOperation_Set (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x00, 0x00, 0x25, 0x0c, 0xca
2018-04-29 11:42:44.357 Detail, Node004, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-04-29 11:42:44.358 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack
2018-04-29 11:42:48.483 Detail, Node004, Received: 0x01, 0x07, 0x00, 0x13, 0x0c, 0x01, 0x01, 0x9d, 0x7a
2018-04-29 11:42:48.483 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x0c received (expected 0x0c)
2018-04-29 11:42:48.483 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-04-29 11:42:48.483 Info, Node004, Node 4 has been marked as asleep
2018-04-29 11:42:48.483 Info, Node004, Node not responding - moving QueryStageComplete command to Wake-Up queue
2018-04-29 11:42:48.484 Detail, Node004, Notification: Notification - NoOperation
2018-04-29 11:42:48.487 Detail, Node004, Notification: Notification - Node Asleep
2018-04-29 11:43:18.843 Detail, Node004, Received: 0x01, 0x1c, 0x00, 0x49, 0x84, 0x04, 0x16, 0x04, 0x07, 0x01, 0x5e, 0x20, 0x86, 0x72, 0x5a, 0x59, 0x85, 0x73, 0x84, 0x80, 0x71, 0x56, 0x70, 0x31, 0x8e, 0x22, 0x9c, 0x98, 0x7a, 0xf1
2018-04-29 11:43:18.843 Detail,
2018-04-29 11:43:18.843 Info, Node004, UPDATE_STATE_NODE_INFO_RECEIVED from node 4
2018-04-29 11:43:18.843 Detail, Node004, AdvanceQueries queryPending=1 queryRetries=0 queryStage=Probe live=1
2018-04-29 11:43:18.844 Info, Node004, Node 4 has been marked as awake
2018-04-29 11:43:18.844 Detail, Node004, Queuing (Query) Query Stage Complete (Probe)
2018-04-29 11:43:18.844 Detail, Node004, Notification: Notification - Node Awake
2018-04-29 11:43:18.847 Detail, Node004, Query Stage Complete (Probe)
2018-04-29 11:43:18.847 Detail, Node004, AdvanceQueries queryPending=0 queryRetries=0 queryStage=WakeUp live=1
2018-04-29 11:43:18.847 Detail, Node004, QueryStage_WakeUp
2018-04-29 11:43:18.848 Detail, Node004, Queuing (WakeUp) WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:43:18.848 Detail, Node004, Queuing (Query) Query Stage Complete (WakeUp)
2018-04-29 11:43:18.848 Detail,
2018-04-29 11:43:18.848 Info, Node004, Sending (WakeUp) message (Callback ID=0x0d, Expected Reply=0x04) - WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:43:18.856 Detail, Node004, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-04-29 11:43:18.856 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack
2018-04-29 11:43:22.953 Detail, Node004, Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x01, 0x01, 0x9a, 0x7c
2018-04-29 11:43:22.953 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d)
2018-04-29 11:43:22.954 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-04-29 11:43:22.954 Info, Node004, Node 4 has been marked as asleep
2018-04-29 11:43:22.954 Info, Node004, Node not responding - moving message to Wake-Up queue: WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:43:22.954 Info, Node004, Node not responding - moving QueryStageComplete command to Wake-Up queue
2018-04-29 11:43:22.954 Detail, Node004, Notification: Notification - Node Asleep
2018-04-29 11:44:02.406 Detail, Node004, Received: 0x01, 0x1c, 0x00, 0x49, 0x84, 0x04, 0x16, 0x04, 0x07, 0x01, 0x5e, 0x20, 0x86, 0x72, 0x5a, 0x59, 0x85, 0x73, 0x84, 0x80, 0x71, 0x56, 0x70, 0x31, 0x8e, 0x22, 0x9c, 0x98, 0x7a, 0xf1
2018-04-29 11:44:02.407 Detail,
2018-04-29 11:44:02.407 Info, Node004, UPDATE_STATE_NODE_INFO_RECEIVED from node 4
2018-04-29 11:44:02.407 Detail, Node004, AdvanceQueries queryPending=1 queryRetries=0 queryStage=WakeUp live=1
2018-04-29 11:44:02.407 Info, Node004, Node 4 has been marked as awake
2018-04-29 11:44:02.407 Detail, Node004, Queuing (WakeUp) WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:44:02.407 Detail, Node004, Queuing (Query) Query Stage Complete (WakeUp)
2018-04-29 11:44:02.407 Detail, Node004, Notification: Notification - Node Awake
2018-04-29 11:44:02.411 Detail,
2018-04-29 11:44:02.411 Info, Node004, Sending (WakeUp) message (Callback ID=0x0d, Expected Reply=0x04) - WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:44:02.419 Detail, Node004, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-04-29 11:44:02.419 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack
2018-04-29 11:44:06.545 Detail, Node004, Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x01, 0x01, 0x9d, 0x7b
2018-04-29 11:44:06.546 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d)
2018-04-29 11:44:06.546 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-04-29 11:44:06.546 Info, Node004, Node 4 has been marked as asleep
2018-04-29 11:44:06.546 Info, Node004, Node not responding - moving message to Wake-Up queue: WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:44:06.546 Info, Node004, Node not responding - moving QueryStageComplete command to Wake-Up queue
2018-04-29 11:44:06.546 Detail, Node004, Notification: Notification - Node Asleep
2018-04-29 11:44:42.324 Detail, Node004, Received: 0x01, 0x1c, 0x00, 0x49, 0x84, 0x04, 0x16, 0x04, 0x07, 0x01, 0x5e, 0x20, 0x86, 0x72, 0x5a, 0x59, 0x85, 0x73, 0x84, 0x80, 0x71, 0x56, 0x70, 0x31, 0x8e, 0x22, 0x9c, 0x98, 0x7a, 0xf1
2018-04-29 11:44:42.324 Detail,
2018-04-29 11:44:42.324 Info, Node004, UPDATE_STATE_NODE_INFO_RECEIVED from node 4
2018-04-29 11:44:42.324 Detail, Node004, AdvanceQueries queryPending=1 queryRetries=0 queryStage=WakeUp live=1
2018-04-29 11:44:42.324 Info, Node004, Node 4 has been marked as awake
2018-04-29 11:44:42.324 Detail, Node004, Queuing (WakeUp) WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:44:42.324 Detail, Node004, Queuing (Query) Query Stage Complete (WakeUp)
2018-04-29 11:44:42.325 Detail, Node004, Notification: Notification - Node Awake
2018-04-29 11:44:42.328 Detail,
2018-04-29 11:44:42.328 Info, Node004, Sending (WakeUp) message (Callback ID=0x0d, Expected Reply=0x04) - WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:44:42.337 Detail, Node004, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-04-29 11:44:42.337 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack
2018-04-29 11:44:46.434 Detail, Node004, Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x01, 0x01, 0x9a, 0x7c
2018-04-29 11:44:46.434 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d)
2018-04-29 11:44:46.434 Info, Node004, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2018-04-29 11:44:46.434 Info, Node004, Node 4 has been marked as asleep
2018-04-29 11:44:46.434 Info, Node004, Node not responding - moving message to Wake-Up queue: WakeUpCmd_IntervalGet (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x84, 0x05, 0x25, 0x0d, 0x4a
2018-04-29 11:44:46.434 Info, Node004, Node not responding - moving QueryStageComplete command to Wake-Up queue
2018-04-29 11:44:46.435 Detail, Node004, Notification: Notification - Node Asleep

ptdalen · April 30, 2018, 6:02pm

Interesting. I spent most of the weekend getting 30 or so zwave devices added. I had an issue here and there. One item I added and came back later to find was having issues was my smoke detector. I have not went back to “fix it” but assumed it was just an issue like the other few devices I had problems with. I’ll try to readd later today and let you know how it goes

coldasijs · April 30, 2018, 9:09pm

After doing allot of searching on the internet, I think I have an idea what the problem might be. In the openzwave documentation I found that apparently the death node function is not always correctly reported by OZW. So OZW does not always know that the controller has marked a node as dead. Here is somebody with a similar problem, The dead nodes are stuck in wakeup. Z-Wave Help: Dead Nodes
When I was busy setting up my smoke sensors I did not take into account that I had to completely setup each detector before continuing with the next one.

As far as I understood to remove death nodes from the controller I need to do a factory reset. I’m not sure if the button on my razberry actually works. I would expect it to give errors in my OZW log if I push it.

As far as I understood now, to remove death nodes I have to do the following:

Exclude nodes from network
remove zwfcg…xml files
do factory reset of the controller (if button does not work, do clean install of zway)

Do I miss anything? Or should I first stop my network before doing the factory reset?

coldasijs · May 1, 2018, 4:50pm

https://z-wave.me/support/hardware-problems/

RaZberry can include and exclude devices, but they are all marked as dead immediately

If you your homeId is 0x55555555 and you see in the log:
SETDATA controller.data.homeId = 1431655765 (0x55555555)
You got one of 5rd generation RaZberry that was powered off during self-test process. We apologize, that happens from time to time too. But hopefully this is easy to solve.
http://IP:8083/JS/Run/var t = [ 0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,
0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,
0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF,0xFF ];
for (var i = 0; i < 1000; i++) { zway.NVMExtWriteLongBuffer(i * t.length, t); }
(this is a link with JS code inside — paste full line in the browser URL bar!)

After this wait for 30 seconds and power off your razberry and power it up again. It will keep lights on for some time (about 5-40 seconds) and go off. After this your homeId will be not 55555555 and Z-Way will be able to include devices and control them.

Hmm it see my razberry has the controller id 0x55555555. So first action when I get home is to wipe home assistant of my sd card and to install the zway software. Sadly I could not run it next to my home assistant install. At least I start to feel confident I will get it fixed. And then I can finally start with the automation stuff

coldasijs · May 4, 2018, 1:52pm

Ok, I got everything working now. Don’t ask me how exactly. After resetting the node id via Zway it still did not work via zway. Factory reset via Zway yielded the same result. After multiple shutdowns I was at the brink of giving up. I was planning to just buy a new controller.
I also posted the same topic on the Zwave.me forum, where I got the response to add the node not as a secure node. I already tried it before but I thought I might as well try it once more. So I did and voila it worked. Becuase I’m pretty sure the Fibaro’s should also work via secure inclusion I tried it again with the same device and again I was able to add the node and initialize.

Now everything is added without too much hassle in HA. It annoys me a bit that I was not able to figure out what was the actual fix. Definitely the controller ID was not ok, but the problems afterwards… Reading more topics on people having issues setting up Zwave I get the feeling it is feeding on frustration some how

Now that this is fixed I can move on to the actual automation.

zarthan · May 4, 2018, 8:00pm

Do understand that battery powered devices spend most of their time sleeping or at least the Z-Wave radio part of their processes is sleeping. Depending on the device they may periodically wake up the Z-wave radio and report things like battery level or similar. Some battery powered devices like remotes, only wake the Z-Wave radio when they have something to report as in a button push but will otherwise not respond to Z-Wave polls etc.

coldasijs · May 5, 2018, 10:40am

Yes I understood this, that’s why I wrote in the opening post:

zarthan · May 5, 2018, 11:42pm

What you saw was to be expected with most battery powered devices. Unless you are trying to change some Z-Wave setting, you don’t need to manually wake them up. At some point they will connect on their own. Since they are not always online like hardwired devices they can’t respond to queries from HA.

coldasijs · May 7, 2018, 6:51pm

Sorry… either I don’t understand you or you didn’t understand the problem I had . Because the behavior I experienced is not expected behavior for battery powered devices. Yes they will go to sleep mode and wake up a given period of time, in my case the fibaro sensors wake up every 6 hours. When everything behave normal the device will go through it iniatilisation process and report all there settings to the controller, like manufacturer and wake up interval etc… This however takes time and can take a day or longer. Waking them up by pushing the button on the device should speed it up allot will speed up this process.
In my case neither waiting nor waking up the device would bring the initialization further the the wakeup stage. Nor would the device report the basic info like manufacturer or the correct wakeup interval.
That the device_id caused the initial problem is clear to me. According to the manufacturer zwave.me this described my case although it did not specify the exact initialization step. Anyway, it works. So I’m happy.

zarthan · May 7, 2018, 7:15pm

I suppose the only important thing is that you are up and going. Good for that! So often people struggle with battery powered devices, expecting them to behave like line powered devices.

On a very distant side issue. Please use “a lot” rather than allot. allot has a totally different meaning. For anyone that may stumble across this, the same goes for alot, actually not a word. I see this so often.