Confused by ZWave system

vincen · May 26, 2017, 10:31am

Hi

I have HA 0.45.1 running on Linux Ubuntu 16.04.2 LTS. I have a USB Zwave key that looks to be recognised correctly in HA (just in case lsusb listing gives me these infos for Zwave dongle:

Bus 003 Device 007: ID 0658:0200 Sigma Designs, Inc.

I have a little eye sensor from Fibaro. I removed battery insulation to start the Fiabro sensor. I clicked on Add Node in HA (nothing visual happens in HA out of button changing color and a short text popup). I triple click the button on the Fibaro to put it in pairing mode (confirmed by the eye going blue) but on HA nothing else happens out of lot of errors in ZWave (see below). Does it sound logical for someone ? and if so what’s problem ?
For now it’s the only Zwave device I have but should have few mores tomorrow !!

Thanks for help

Vincèn

2017-05-26 11:23:51.033 Always, OpenZwave Version 1.4.2508 Starting Up
2017-05-26 11:23:52.909 Info, Setting Up Provided Network Key for Secure Communications
2017-05-26 11:23:52.909 Warning, Failed - Network Key Not Set
2017-05-26 11:23:52.909 Info, mgr,     Added driver for controller /dev/ttyACM0
2017-05-26 11:23:52.909 Info,   Opening controller /dev/ttyACM0
2017-05-26 11:23:52.909 Info, Trying to open serial port /dev/ttyACM0 (attempt 1)
2017-05-26 11:23:52.909 Info, Serial port /dev/ttyACM0 opened (attempt 1)
2017-05-26 11:23:52.910 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-05-26 11:23:52.910 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-05-26 11:23:52.910 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-05-26 11:23:52.910 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-05-26 11:23:52.910 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-05-26 11:23:52.910 Detail, 
2017-05-26 11:23:52.910 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-05-26 11:23:52.912 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x30, 0x35, 0x00, 0x01, 0x97
2017-05-26 11:23:52.912 Detail, 
2017-05-26 11:23:52.912 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2017-05-26 11:23:52.912 Info, contrlr,     Static Controller library, version Z-Wave 4.05
2017-05-26 11:23:52.912 Detail, Node045,   Expected reply was received
2017-05-26 11:23:52.912 Detail, Node045,   Message transaction complete
2017-05-26 11:23:52.912 Detail, 
2017-05-26 11:23:52.912 Detail, contrlr, Removing current message
2017-05-26 11:23:52.912 Detail, 
2017-05-26 11:23:52.912 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-05-26 11:23:52.914 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xc9, 0x67, 0x3d, 0xf8, 0x01, 0xbc
2017-05-26 11:23:52.914 Detail, 
2017-05-26 11:23:52.914 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xc9673df8.  Our node ID = 1
2017-05-26 11:23:52.914 Detail, Node103,   Expected reply was received
2017-05-26 11:23:52.914 Detail, Node103,   Message transaction complete
2017-05-26 11:23:52.914 Detail, 
2017-05-26 11:23:52.914 Detail, contrlr, Removing current message
2017-05-26 11:23:52.914 Detail, 
2017-05-26 11:23:52.914 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-05-26 11:23:52.915 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x28, 0xd7
2017-05-26 11:23:52.915 Detail, 
2017-05-26 11:23:52.915 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2017-05-26 11:23:52.915 Info, contrlr,     There is no SUC ID Server (SIS) in this network.
2017-05-26 11:23:52.915 Info, contrlr,     The PC controller is a primary controller.
2017-05-26 11:23:52.915 Detail, Node215,   Expected reply was received
2017-05-26 11:23:52.915 Detail, Node215,   Message transaction complete
2017-05-26 11:23:52.915 Detail, 
2017-05-26 11:23:52.915 Detail, contrlr, Removing current message
2017-05-26 11:23:52.915 Detail, 
2017-05-26 11:23:52.915 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-05-26 11:23:52.919 Detail, contrlr,   Received: 0x01, 0x2b, 0x01, 0x07, 0x05, 0x05, 0x01, 0x15, 0x04, 0x00, 0x00, 0x01, 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, 0x0e
2017-05-26 11:23:52.919 Detail, 
2017-05-26 11:23:52.919 Info, contrlr,  Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2017-05-26 11:23:52.919 Info, contrlr,     Serial API Version:   5.5
2017-05-26 11:23:52.919 Info, contrlr,     Manufacturer ID:      0x0115
2017-05-26 11:23:52.919 Info, contrlr,     Product Type:         0x0400
2017-05-26 11:23:52.919 Info, contrlr,     Product ID:           0x0001
2017-05-26 11:23:52.919 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2017-05-26 11:23:52.919 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2017-05-26 11:23:52.919 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2017-05-26 11:23:52.919 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2017-05-26 11:23:52.919 Detail, Node005,   Expected reply was received
2017-05-26 11:23:52.919 Detail, Node005,   Message transaction complete
2017-05-26 11:23:52.919 Detail, 
2017-05-26 11:23:52.919 Detail, contrlr, Removing current message
2017-05-26 11:23:52.919 Detail, 
2017-05-26 11:23:52.919 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-05-26 11:23:52.921 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2017-05-26 11:23:52.921 Detail, 
2017-05-26 11:23:52.921 Info, contrlr, Received reply to GET_SUC_NODE_ID.  Node ID = 0
2017-05-26 11:23:52.921 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node
2017-05-26 11:23:52.921 Detail, Node172,   Expected reply was received
2017-05-26 11:23:52.921 Detail, Node172,   Message transaction complete
2017-05-26 11:23:52.921 Detail, 
2017-05-26 11:23:52.921 Detail, contrlr, Removing current message
2017-05-26 11:23:52.921 Detail, 
2017-05-26 11:23:52.921 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2017-05-26 11:23:52.976 Detail, contrlr,   Received: 0x01, 0x25, 0x01, 0x1c, 0x01, 0x20, 0x88, 0xd8, 0x82, 0xa9, 0x7a, 0x70, 0x09, 0xbc, 0xe1, 0x7a, 0x23, 0x43, 0x45, 0x8a, 0xc9, 0xd3, 0xeb, 0xe1, 0xde, 0xff, 0xfc, 0x8c, 0x32, 0x27, 0x45, 0x04, 0x84, 0xe9, 0xce, 0x1c, 0x04, 0x3d, 0x85
2017-05-26 11:23:52.976 Detail, 
2017-05-26 11:23:52.976 Info, contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2017-05-26 11:23:52.976 Detail, Node032,   Expected reply was received
2017-05-26 11:23:52.976 Detail, Node032,   Message transaction complete
2017-05-26 11:23:52.976 Detail, 
2017-05-26 11:23:52.976 Detail, contrlr, Removing current message
2017-05-26 11:23:52.976 Detail, 
2017-05-26 11:23:52.976 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x02) - FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2017-05-26 11:23:53.075 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
2017-05-26 11:23:53.075 Detail, 
2017-05-26 11:23:53.075 Info, mgr,     Driver with Home ID of 0xc9673df8 is now ready.
2017-05-26 11:23:53.075 Info, 
2017-05-26 11:23:53.076 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2017-05-26 11:23:53.076 Info, contrlr,     Node 001 - Known
2017-05-26 11:23:53.076 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2017-05-26 11:23:53.076 Detail, Node001, QueryStage_CacheLoad
2017-05-26 11:23:53.076 Info, Node001, Node Identity Codes: 0115:0400:0001
2017-05-26 11:23:53.076 Detail, Node001, QueryStage_Associations
2017-05-26 11:23:53.076 Detail, Node001, QueryStage_Neighbors
2017-05-26 11:23:53.076 Detail, contrlr, Requesting routing info (neighbor list) for Node 1
2017-05-26 11:23:53.076 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2017-05-26 11:23:53.076 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2017-05-26 11:23:53.076 Detail,   Expected reply was received
2017-05-26 11:23:53.076 Detail,   Message transaction complete
2017-05-26 11:23:53.076 Detail, 
2017-05-26 11:23:53.076 Detail, contrlr, Removing current message
2017-05-26 11:23:53.076 Detail, Node001, Notification: DriverReady
2017-05-26 11:23:53.077 Detail, Node001, Notification: NodeAdded
2017-05-26 11:23:53.079 Detail, Node001, Notification: NodeProtocolInfo
2017-05-26 11:23:53.080 Detail, Node001, Notification: EssentialNodeQueriesComplete
2017-05-26 11:23:53.080 Detail, Node001, Notification: ValueAdded
2017-05-26 11:23:53.080 Detail, Node001, Notification: NodeNaming
2017-05-26 11:23:53.080 Detail, 
2017-05-26 11:23:53.080 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x06) - FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2017-05-26 11:23:53.086 Detail, contrlr,   Received: 0x01, 0x05, 0x01, 0x06, 0x64, 0x0f, 0x96
2017-05-26 11:23:53.086 Detail, 
2017-05-26 11:23:53.086 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_SET_TIMEOUTS
2017-05-26 11:23:53.086 Detail, Node015,   Expected reply was received
2017-05-26 11:23:53.086 Detail, Node015,   Message transaction complete
2017-05-26 11:23:53.086 Detail, 
2017-05-26 11:23:53.086 Detail, contrlr, Removing current message
2017-05-26 11:23:53.086 Detail, 
2017-05-26 11:23:53.086 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
2017-05-26 11:23:53.087 Detail, contrlr, Removing current message
2017-05-26 11:23:53.087 Detail, 
2017-05-26 11:23:53.087 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
2017-05-26 11:23:53.093 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
2017-05-26 11:23:53.093 Detail, 
2017-05-26 11:23:53.093 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2017-05-26 11:23:53.093 Info, Node001,     Neighbors of this node are:
2017-05-26 11:23:53.093 Info, Node001,  (none reported)
2017-05-26 11:23:53.093 Detail,   Expected reply was received
2017-05-26 11:23:53.093 Detail,   Message transaction complete
2017-05-26 11:23:53.093 Detail, 
2017-05-26 11:23:53.093 Detail, Node001, Removing current message
2017-05-26 11:23:53.093 Detail, Node001, Query Stage Complete (Neighbors)
2017-05-26 11:23:53.093 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2017-05-26 11:23:53.093 Detail, Node001, QueryStage_Session
2017-05-26 11:23:53.093 Detail, Node001, QueryStage_Dynamic
2017-05-26 11:23:53.093 Detail, Node001, QueryStage_Configuration
2017-05-26 11:23:53.093 Detail, Node001, QueryStage_Complete
2017-05-26 11:23:53.093 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2017-05-26 11:23:53.093 Warning, CheckCompletedNodeQueries all=1, deadFound=0 sleepingOnly=1
2017-05-26 11:23:53.093 Info,          Node query processing complete.
2017-05-26 11:23:53.093 Detail, Node001, Notification: NodeQueriesComplete
2017-05-26 11:23:53.093 Detail, contrlr, Notification: AllNodesQueried
2017-05-26 11:48:35.737 Detail, Queuing (Controller) Add Device
2017-05-26 11:48:35.737 Info, Add Device
2017-05-26 11:48:35.737 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0a, 0x7b
2017-05-26 11:48:35.737 Detail, Notification: ControllerCommand - Starting
2017-05-26 11:48:35.737 Detail, 
2017-05-26 11:48:35.737 Info, contrlr, Sending (Command) message (Callback ID=0x0a, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0a, 0x7b
2017-05-26 11:48:35.740 Detail, contrlr,   Received: 0x01, 0x07, 0x00, 0x4a, 0x0a, 0x01, 0x00, 0x00, 0xb9
2017-05-26 11:48:35.740 Detail, 
2017-05-26 11:48:35.740 Info, contrlr, FUNC_ID_ZW_ADD_NODE_TO_NETWORK:
2017-05-26 11:48:35.740 Info, contrlr, ADD_NODE_STATUS_LEARN_READY
2017-05-26 11:48:35.740 Detail, Node001,   Expected callbackId was received
2017-05-26 11:48:35.740 Detail, Node001,   Expected reply was received
2017-05-26 11:48:35.740 Detail, Node001,   Message transaction complete
2017-05-26 11:48:35.740 Detail, 
2017-05-26 11:48:35.740 Detail, contrlr, Removing current message
2017-05-26 11:48:35.740 Detail, Notification: ControllerCommand - Waiting
2017-05-26 11:49:09.134 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=ProtocolInfo live=1
2017-05-26 11:49:09.134 Detail, Node001, QueryStage_Probe
2017-05-26 11:49:09.134 Detail, Node001, QueryStage_WakeUp
2017-05-26 11:49:09.134 Detail, Node001, QueryStage_ManufacturerSpecific1
2017-05-26 11:49:09.134 Detail, Node001, Load Controller Manufacturer Specific Config
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_NodePlusInfo
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_SecurityReport
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_ManufacturerSpecific2
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_Versions
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_Instances
2017-05-26 11:49:09.142 Info, Node001, Essential node queries are complete
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_Static
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_Associations
2017-05-26 11:49:09.142 Detail, Node001, QueryStage_Neighbors
2017-05-26 11:49:09.142 Detail, Requesting routing info (neighbor list) for Node 1
2017-05-26 11:49:09.142 Detail, Node001, Notification: EssentialNodeQueriesComplete
2017-05-26 11:49:09.142 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2017-05-26 11:49:09.142 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2017-05-26 11:49:09.142 Detail, 
2017-05-26 11:49:09.142 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
2017-05-26 11:49:09.146 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
2017-05-26 11:49:09.146 Detail, 
2017-05-26 11:49:09.146 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2017-05-26 11:49:09.146 Info, Node001,     Neighbors of this node are:
2017-05-26 11:49:09.146 Info, Node001,  (none reported)
2017-05-26 11:49:09.146 Detail,   Expected reply was received
2017-05-26 11:49:09.146 Detail,   Message transaction complete
2017-05-26 11:49:09.146 Detail, 
2017-05-26 11:49:09.146 Detail, Node001, Removing current message
2017-05-26 11:49:12.773 Detail, Node001, Notification: NodeNaming
2017-05-26 11:53:26.811 Warning, Exception: Manager.cpp:2499 - 102 - ValueID passed to GetValueFloatPrecision is not a Decimal Value
2017-05-26 11:53:26.811 Warning, Exception: Manager.cpp:2499 - 102 - ValueID passed to GetValueFloatPrecision is not a Decimal Value
2017-05-26 11:55:02.409 Detail, Node001, Queuing (Controller) Request Node Neighbor Update
2017-05-26 12:03:19.662 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=ProtocolInfo live=1
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_Probe
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_WakeUp
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_ManufacturerSpecific1
2017-05-26 12:03:19.662 Detail, Node001, Load Controller Manufacturer Specific Config
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_NodePlusInfo
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_SecurityReport
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_ManufacturerSpecific2
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_Versions
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_Instances
2017-05-26 12:03:19.662 Info, Node001, Essential node queries are complete
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_Static
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_Associations
2017-05-26 12:03:19.662 Detail, Node001, QueryStage_Neighbors
2017-05-26 12:03:19.662 Detail, Requesting routing info (neighbor list) for Node 1
2017-05-26 12:03:19.662 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2017-05-26 12:03:19.662 Detail, Node001, Notification: EssentialNodeQueriesComplete
2017-05-26 12:03:19.662 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2017-05-26 12:03:19.662 Detail, 
2017-05-26 12:03:19.662 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
2017-05-26 12:03:19.666 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
2017-05-26 12:03:19.667 Detail, 
2017-05-26 12:03:19.667 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2017-05-26 12:03:19.667 Info, Node001,     Neighbors of this node are:
2017-05-26 12:03:19.667 Info, Node001,  (none reported)
2017-05-26 12:03:19.667 Detail,   Expected reply was received
2017-05-26 12:03:19.667 Detail,   Message transaction complete
2017-05-26 12:03:19.667 Detail, 
2017-05-26 12:03:19.667 Detail, Node001, Removing current message
2017-05-26 12:03:36.307 Info, Cancel Add Node
2017-05-26 12:03:36.307 Detail, contrlr, Queuing (Command) Add Node Stop: 0x01, 0x04, 0x00, 0x4a, 0x05, 0xb4
2017-05-26 12:03:36.307 Detail, Notification: ControllerCommand - Canceled
2017-05-26 12:03:36.307 Detail, 
2017-05-26 12:03:36.307 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x4a) - Add Node Stop: 0x01, 0x04, 0x00, 0x4a, 0x05, 0xb4
2017-05-26 12:03:39.939 Info, Soft-resetting the Z-Wave controller chip
2017-05-26 12:03:39.939 Detail, contrlr, Queuing (Command) Soft-resetting the Z-Wave controller chip: 0x01, 0x03, 0x00, 0x08, 0xf4
2017-05-26 12:03:46.308 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:03:46.308 Detail, contrlr, Removing current message
2017-05-26 12:03:46.308 Detail, contrlr, Notification: Notification - TimeOut
2017-05-26 12:03:46.308 Detail, Notification: ControllerCommand - Error - Failed
2017-05-26 12:03:46.308 Detail, 
2017-05-26 12:03:46.308 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x00) - Soft-resetting the Z-Wave controller chip: 0x01, 0x03, 0x00, 0x08, 0xf4
2017-05-26 12:03:46.309 Detail, contrlr, Removing current message
2017-05-26 12:03:46.309 Info, Requesting Neighbor Update for node 1
2017-05-26 12:03:46.309 Detail, Node001, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0b, 0xb8
2017-05-26 12:03:46.309 Detail, Notification: ControllerCommand - Starting
2017-05-26 12:03:46.309 Detail, 
2017-05-26 12:03:46.309 Info, Node001, Sending (Command) message (Callback ID=0x0b, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x0b, 0xb8
2017-05-26 12:03:47.309 Error, Node001, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:03:47.309 Detail, Node001, Removing current message
2017-05-26 12:03:47.309 Detail, Node001, Notification: Notification - TimeOut
2017-05-26 12:03:47.310 Detail, Notification: ControllerCommand - Error - Failed
2017-05-26 12:03:47.310 Detail, Node001, Query Stage Complete (Neighbors)
2017-05-26 12:03:47.310 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2017-05-26 12:03:47.310 Detail, Node001, QueryStage_Session
2017-05-26 12:03:47.310 Detail, Node001, QueryStage_Dynamic
2017-05-26 12:03:47.310 Detail, Node001, QueryStage_Configuration
2017-05-26 12:03:47.310 Detail, Node001, QueryStage_Complete
2017-05-26 12:03:47.310 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2017-05-26 12:03:47.310 Detail, Node001, Notification: NodeQueriesComplete
2017-05-26 12:03:47.311 Detail, Node001, Query Stage Complete (Neighbors)
2017-05-26 12:03:47.311 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Complete live=1
2017-05-26 12:03:47.311 Detail, Node001, QueryStage_Complete
2017-05-26 12:03:47.311 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2017-05-26 12:03:47.311 Detail, Node001, Notification: NodeQueriesComplete
2017-05-26 12:04:58.569 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=ProtocolInfo live=1
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_Probe
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_WakeUp
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_ManufacturerSpecific1
2017-05-26 12:04:58.569 Detail, Node001, Load Controller Manufacturer Specific Config
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_NodePlusInfo
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_SecurityReport
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_ManufacturerSpecific2
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_Versions
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_Instances
2017-05-26 12:04:58.569 Info, Node001, Essential node queries are complete
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_Static
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_Associations
2017-05-26 12:04:58.569 Detail, Node001, QueryStage_Neighbors
2017-05-26 12:04:58.569 Detail, Requesting routing info (neighbor list) for Node 1
2017-05-26 12:04:58.569 Detail, Node001, Notification: EssentialNodeQueriesComplete
2017-05-26 12:04:58.569 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2017-05-26 12:04:58.569 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2017-05-26 12:04:58.570 Detail, 
2017-05-26 12:04:58.570 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
2017-05-26 12:04:59.570 Error, Node001, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:04:59.570 Detail, Node001, Removing current message
2017-05-26 12:04:59.570 Detail, Node001, Notification: Notification - TimeOut
2017-05-26 12:04:59.570 Detail, Node001, Query Stage Complete (Neighbors)
2017-05-26 12:04:59.570 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2017-05-26 12:04:59.570 Detail, Node001, QueryStage_Session
2017-05-26 12:04:59.570 Detail, Node001, QueryStage_Dynamic
2017-05-26 12:04:59.570 Detail, Node001, QueryStage_Configuration
2017-05-26 12:04:59.570 Detail, Node001, QueryStage_Complete
2017-05-26 12:04:59.570 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2017-05-26 12:04:59.570 Detail, Node001, Notification: NodeQueriesComplete
2017-05-26 12:13:35.730 Detail, Queuing (Controller) Remove Device
2017-05-26 12:13:35.730 Info, Remove Device
2017-05-26 12:13:35.730 Detail, contrlr, Queuing (Command) ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0c, 0x3c
2017-05-26 12:13:35.730 Detail, Notification: ControllerCommand - Starting
2017-05-26 12:13:35.731 Detail, 
2017-05-26 12:13:35.731 Info, contrlr, Sending (Command) message (Callback ID=0x0c, Expected Reply=0x4b) - ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0c, 0x3c
2017-05-26 12:13:36.731 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:13:36.731 Detail, contrlr, Removing current message
2017-05-26 12:13:36.732 Detail, contrlr, Notification: Notification - TimeOut
2017-05-26 12:13:36.732 Detail, Notification: ControllerCommand - Error - Failed
2017-05-26 12:14:11.443 Detail, Queuing (Controller) Add Device
2017-05-26 12:14:11.443 Info, Add Device
2017-05-26 12:14:11.443 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-05-26 12:14:11.443 Detail, Notification: ControllerCommand - Starting
2017-05-26 12:14:11.445 Detail, 
2017-05-26 12:14:11.445 Info, contrlr, Sending (Command) message (Callback ID=0x0d, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-05-26 12:14:12.445 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:14:12.445 Detail, contrlr, Removing current message
2017-05-26 12:14:12.445 Detail, contrlr, Notification: Notification - TimeOut
2017-05-26 12:14:12.445 Detail, Notification: ControllerCommand - Error - Failed
2017-05-26 12:16:41.770 Detail, Queuing (Controller) Add Device
2017-05-26 12:16:41.770 Info, Add Device
2017-05-26 12:16:41.770 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0e, 0x7f
2017-05-26 12:16:41.770 Detail, Notification: ControllerCommand - Starting
2017-05-26 12:16:41.770 Detail, 
2017-05-26 12:16:41.770 Info, contrlr, Sending (Command) message (Callback ID=0x0e, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0e, 0x7f
2017-05-26 12:16:42.770 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:16:42.770 Detail, contrlr, Removing current message
2017-05-26 12:16:42.770 Detail, contrlr, Notification: Notification - TimeOut
2017-05-26 12:16:42.770 Detail, Notification: ControllerCommand - Error - Failed
2017-05-26 12:17:35.843 Detail, Queuing (Controller) Add Device
2017-05-26 12:17:35.844 Info, Add Device
2017-05-26 12:17:35.844 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0f, 0x7e
2017-05-26 12:17:35.844 Detail, Notification: ControllerCommand - Starting
2017-05-26 12:17:35.845 Detail, 
2017-05-26 12:17:35.845 Info, contrlr, Sending (Command) message (Callback ID=0x0f, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0f, 0x7e
2017-05-26 12:17:36.845 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:17:36.845 Detail, contrlr, Removing current message
2017-05-26 12:17:36.845 Detail, contrlr, Notification: Notification - TimeOut
2017-05-26 12:17:36.845 Detail, Notification: ControllerCommand - Error - Failed
2017-05-26 12:20:17.530 Detail, Node001, Queuing (Controller) Request Node Neighbor Update
2017-05-26 12:20:17.530 Info, Requesting Neighbor Update for node 1
2017-05-26 12:20:17.530 Detail, Node001, Queuing (Command) ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x10, 0xa3
2017-05-26 12:20:17.530 Detail, Notification: ControllerCommand - Starting
2017-05-26 12:20:17.530 Detail, 
2017-05-26 12:20:17.530 Info, Node001, Sending (Command) message (Callback ID=0x10, Expected Reply=0x48) - ControllerCommand_RequestNodeNeighborUpdate (Node=1): 0x01, 0x05, 0x00, 0x48, 0x01, 0x10, 0xa3
2017-05-26 12:20:18.531 Error, Node001, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:20:18.531 Detail, Node001, Removing current message
2017-05-26 12:20:18.531 Detail, Node001, Notification: Notification - TimeOut
2017-05-26 12:20:18.531 Detail, Notification: ControllerCommand - Error - Failed

BendedArrow · May 26, 2017, 11:28am

It looks like your controller is not taking commands for some reason. It can be seen, but you cannot do anything with it:

2017-05-26 12:13:35.731 Info, contrlr, Sending (Command) message (Callback ID=0x0c, Expected Reply=0x4b) - ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0c, 0x3c
2017-05-26 12:13:36.731 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:13:36.731 Detail, contrlr, Removing current message
2017-05-26 12:13:36.732 Detail, contrlr, Notification: Notification - TimeOut
**2017-05-26 12:13:36.732 Detail, Notification: ControllerCommand - Error - Failed**
2017-05-26 12:14:11.443 Detail, Queuing (Controller) Add Device
2017-05-26 12:14:11.443 Info, Add Device
2017-05-26 12:14:11.443 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-05-26 12:14:11.443 Detail, Notification: ControllerCommand - Starting
2017-05-26 12:14:11.445 Detail, 
2017-05-26 12:14:11.445 Info, contrlr, Sending (Command) message (Callback ID=0x0d, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-05-26 12:14:12.445 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-05-26 12:14:12.445 Detail, contrlr, Removing current message
2017-05-26 12:14:12.445 Detail, contrlr, Notification: Notification - TimeOut

vincen · May 26, 2017, 12:27pm

@BendedArrow any reasons it would do that ? or what can I do to reset it ? or redo configuration somewhere ?

vincen · May 29, 2017, 6:07am

if it can help, here is what I get in log of OZW when I restart HA, may it help ??

Thanks

2017-05-29 08:03:09.624 Always, OpenZwave Version 1.4.2508 Starting Up
2017-05-29 08:03:12.872 Info, Setting Up Provided Network Key for Secure Communications
2017-05-29 08:03:12.872 Warning, Failed - Network Key Not Set
2017-05-29 08:03:12.872 Info, mgr, Added driver for controller /dev/ttyACM1
2017-05-29 08:03:12.872 Info, Opening controller /dev/ttyACM1
2017-05-29 08:03:12.872 Info, Trying to open serial port /dev/ttyACM1 (attempt 1)
2017-05-29 08:03:12.872 Info, Serial port /dev/ttyACM1 opened (attempt 1)
2017-05-29 08:03:12.872 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-05-29 08:03:12.872 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-05-29 08:03:12.872 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-05-29 08:03:12.873 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-05-29 08:03:12.873 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-05-29 08:03:12.873 Detail,
2017-05-29 08:03:12.873 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-05-29 08:03:12.874 Detail, contrlr, Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x30, 0x35, 0x00, 0x01, 0x97
2017-05-29 08:03:12.874 Detail,
2017-05-29 08:03:12.874 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2017-05-29 08:03:12.874 Info, contrlr, Static Controller library, version Z-Wave 4.05
2017-05-29 08:03:12.874 Detail, Node045, Expected reply was received
2017-05-29 08:03:12.874 Detail, Node045, Message transaction complete
2017-05-29 08:03:12.874 Detail,
2017-05-29 08:03:12.874 Detail, contrlr, Removing current message
2017-05-29 08:03:12.874 Detail,
2017-05-29 08:03:12.874 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-05-29 08:03:12.876 Detail, contrlr, Received: 0x01, 0x08, 0x01, 0x20, 0xc9, 0x67, 0x3d, 0xf8, 0x01, 0xbc
2017-05-29 08:03:12.877 Detail,
2017-05-29 08:03:12.877 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xc9673df8. Our node ID = 1
2017-05-29 08:03:12.877 Detail, Node103, Expected reply was received
2017-05-29 08:03:12.877 Detail, Node103, Message transaction complete
2017-05-29 08:03:12.877 Detail,
2017-05-29 08:03:12.877 Detail, contrlr, Removing current message
2017-05-29 08:03:12.877 Detail,
2017-05-29 08:03:12.877 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-05-29 08:03:12.878 Detail, contrlr, Received: 0x01, 0x04, 0x01, 0x05, 0x08, 0xf7
2017-05-29 08:03:12.878 Detail,
2017-05-29 08:03:12.878 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2017-05-29 08:03:12.878 Info, contrlr, There is no SUC ID Server (SIS) in this network.
2017-05-29 08:03:12.878 Info, contrlr, The PC controller is a primary controller.
2017-05-29 08:03:12.878 Detail, Node247, Expected reply was received
2017-05-29 08:03:12.878 Detail, Node247, Message transaction complete
2017-05-29 08:03:12.878 Detail,
2017-05-29 08:03:12.878 Detail, contrlr, Removing current message
2017-05-29 08:03:12.878 Detail,
2017-05-29 08:03:12.878 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-05-29 08:03:12.882 Detail, contrlr, Received: 0x01, 0x2b, 0x01, 0x07, 0x05, 0x05, 0x01, 0x15, 0x04, 0x00, 0x00, 0x01, 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, 0x0e
2017-05-29 08:03:12.882 Detail,
2017-05-29 08:03:12.882 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2017-05-29 08:03:12.882 Info, contrlr, Serial API Version: 5.5
2017-05-29 08:03:12.882 Info, contrlr, Manufacturer ID: 0x0115
2017-05-29 08:03:12.882 Info, contrlr, Product Type: 0x0400
2017-05-29 08:03:12.882 Info, contrlr, Product ID: 0x0001
2017-05-29 08:03:12.882 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2017-05-29 08:03:12.882 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2017-05-29 08:03:12.882 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2017-05-29 08:03:12.882 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2017-05-29 08:03:12.882 Detail, Node005, Expected reply was received
2017-05-29 08:03:12.882 Detail, Node005, Message transaction complete
2017-05-29 08:03:12.882 Detail,
2017-05-29 08:03:12.882 Detail, contrlr, Removing current message
2017-05-29 08:03:12.882 Detail,
2017-05-29 08:03:12.882 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-05-29 08:03:12.883 Detail, contrlr, Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2017-05-29 08:03:12.883 Detail,
2017-05-29 08:03:12.883 Info, contrlr, Received reply to GET_SUC_NODE_ID. Node ID = 0
2017-05-29 08:03:12.883 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node
2017-05-29 08:03:12.883 Detail, Node172, Expected reply was received
2017-05-29 08:03:12.883 Detail, Node172, Message transaction complete
2017-05-29 08:03:12.883 Detail,
2017-05-29 08:03:12.883 Detail, contrlr, Removing current message
2017-05-29 08:03:12.883 Detail,
2017-05-29 08:03:12.883 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2017-05-29 08:03:12.938 Detail, contrlr, Received: 0x01, 0x25, 0x01, 0x1c, 0x01, 0x20, 0x7a, 0xfc, 0x5e, 0x63, 0x6b, 0x93, 0x7b, 0xe7, 0x81, 0x34, 0x7c, 0xd9, 0xf1, 0x9e, 0xb4, 0xe3, 0xf0, 0x62, 0xfb, 0x86, 0x23, 0x9b, 0xd8, 0x92, 0xd1, 0x95, 0x49, 0x40, 0x50, 0x65, 0x6c, 0x38, 0x20
2017-05-29 08:03:12.939 Detail,
2017-05-29 08:03:12.939 Info, contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2017-05-29 08:03:12.939 Detail, Node032, Expected reply was received
2017-05-29 08:03:12.939 Detail, Node032, Message transaction complete
2017-05-29 08:03:12.939 Detail,
2017-05-29 08:03:12.939 Detail, contrlr, Removing current message
2017-05-29 08:03:12.939 Detail,
2017-05-29 08:03:12.939 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x02) - FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2017-05-29 08:03:13.038 Detail, contrlr, Received: 0x01, 0x25, 0x01, 0x02, 0x05, 0x00, 0x1d, 0x03, 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, 0xc7
2017-05-29 08:03:13.038 Detail,
2017-05-29 08:03:13.038 Info, mgr, Driver with Home ID of 0xc9673df8 is now ready.
2017-05-29 08:03:13.038 Info,
2017-05-29 08:03:13.039 Info, Node002, CentralScene - Created 0
2017-05-29 08:03:13.039 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2017-05-29 08:03:13.039 Info, contrlr, Node 001 - Known
2017-05-29 08:03:13.039 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2017-05-29 08:03:13.039 Detail, Node001, QueryStage_CacheLoad
2017-05-29 08:03:13.039 Info, Node001, Node Identity Codes: 0115:0400:0001
2017-05-29 08:03:13.039 Detail, Node001, QueryStage_Associations
2017-05-29 08:03:13.039 Detail, Node001, QueryStage_Neighbors
2017-05-29 08:03:13.039 Detail, contrlr, Requesting routing info (neighbor list) for Node 1
2017-05-29 08:03:13.039 Detail, Node001, Queuing (Command) Get Routing Info (Node=1): 0x01, 0x07, 0x00, 0x80, 0x01, 0x00, 0x00, 0x03, 0x7a
2017-05-29 08:03:13.039 Detail, Node001, Queuing (Query) Query Stage Complete (Neighbors)
2017-05-29 08:03:13.039 Info, contrlr, Node 002 - Known
2017-05-29 08:03:13.039 Detail, Node002, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Probe live=1
2017-05-29 08:03:13.039 Detail, Node002, QueryStage_Probe
2017-05-29 08:03:13.039 Info, Node002, NoOperation::Set - Routing=true
2017-05-29 08:03:13.039 Detail, Node002, Queuing (NoOp) NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xca
2017-05-29 08:03:13.039 Detail, Node002, Queuing (Query) Query Stage Complete (Probe)
2017-05-29 08:03:13.039 Detail, Expected reply was received
2017-05-29 08:03:13.039 Detail, Message transaction complete
2017-05-29 08:03:13.039 Detail,
2017-05-29 08:03:13.039 Detail, contrlr, Removing current message
2017-05-29 08:03:13.039 Detail, Node001, Notification: DriverReady
2017-05-29 08:03:13.040 Detail, Node001, Notification: NodeAdded
2017-05-29 08:03:13.043 Detail, Node001, Notification: NodeProtocolInfo
2017-05-29 08:03:13.043 Detail, Node001, Notification: EssentialNodeQueriesComplete
2017-05-29 08:03:13.044 Detail, Node001, Notification: ValueAdded
2017-05-29 08:03:13.044 Detail, Node001, Notification: NodeNaming
2017-05-29 08:03:13.044 Detail, Node002, Notification: NodeAdded
2017-05-29 08:03:13.046 Detail, Node002, Notification: NodeProtocolInfo
2017-05-29 08:03:13.046 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.046 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.047 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.048 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.048 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.048 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.048 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.048 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.048 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.048 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.049 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.049 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.049 Detail, Node002, Notification: ValueAdded
2017-05-29 08:03:13.049 Detail,
2017-05-29 08:03:13.049 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x06) - FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2017-05-29 08:03:13.050 Detail, contrlr, Received: 0x01, 0x05, 0x01, 0x06, 0x64, 0x0f, 0x96
2017-05-29 08:03:13.050 Detail,
2017-05-29 08:03:13.050 Info, contrlr, Received reply to FUNC_ID_SERIAL_API_SET_TIMEOUTS
2017-05-29 08:03:13.050 Detail, Node015, Expected reply was received
2017-05-29 08:03:13.051 Detail, Node015, Message transaction complete
2017-05-29 08:03:13.051 Detail,
2017-05-29 08:03:13.051 Detail, contrlr, Removing current message
2017-05-29 08:03:13.051 Detail,
2017-05-29 08:03:13.051 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
2017-05-29 08:03:13.052 Detail, contrlr, Removing current message
2017-05-29 08:03:13.052 Detail,
2017-05-29 08:03:13.052 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
2017-05-29 08:03:13.057 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
2017-05-29 08:03:13.057 Detail,
2017-05-29 08:03:13.057 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2017-05-29 08:03:13.057 Info, Node001, Neighbors of this node are:
2017-05-29 08:03:13.057 Info, Node001, (none reported)
2017-05-29 08:03:13.057 Detail, Expected reply was received
2017-05-29 08:03:13.057 Detail, Message transaction complete
2017-05-29 08:03:13.057 Detail,
2017-05-29 08:03:13.057 Detail, Node001, Removing current message
2017-05-29 08:03:13.057 Detail,
2017-05-29 08:03:13.057 Info, Node002, Sending (NoOp) message (Callback ID=0x0a, Expected Reply=0x13) - NoOperation_Set (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x00, 0x00, 0x25, 0x0a, 0xca
2017-05-29 08:03:13.069 Detail, Node002, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2017-05-29 08:03:13.069 Detail, Node002, ZW_SEND_DATA delivered to Z-Wave stack
2017-05-29 08:03:17.197 Detail, Node002, Received: 0x01, 0x07, 0x00, 0x13, 0x0a, 0x01, 0x01, 0x9d, 0x7c
2017-05-29 08:03:17.197 Detail, Node002, ZW_SEND_DATA Request with callback ID 0x0a received (expected 0x0a)
2017-05-29 08:03:17.197 Info, Node002, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2017-05-29 08:03:17.197 Info, Node002, Node 2 has been marked as asleep
2017-05-29 08:03:17.197 Info, Node002, Node not responding - moving QueryStageComplete command to Wake-Up queue
2017-05-29 08:03:17.197 Detail, Node002, Notification: Notification - NoOperation
2017-05-29 08:03:17.197 Detail, Node002, Notification: Notification - Node Asleep
2017-05-29 08:03:17.198 Detail, Node001, Query Stage Complete (Neighbors)
2017-05-29 08:03:17.198 Detail, Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Session live=1
2017-05-29 08:03:17.198 Detail, Node001, QueryStage_Session
2017-05-29 08:03:17.198 Detail, Node001, QueryStage_Dynamic
2017-05-29 08:03:17.198 Detail, Node001, QueryStage_Configuration
2017-05-29 08:03:17.198 Detail, Node001, QueryStage_Complete
2017-05-29 08:03:17.198 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2017-05-29 08:03:17.198 Warning, CheckCompletedNodeQueries all=0, deadFound=0 sleepingOnly=1
2017-05-29 08:03:17.198 Info, Node query processing complete except for sleeping nodes.
2017-05-29 08:03:17.198 Detail, Node001, Notification: NodeQueriesComplete
2017-05-29 08:03:17.198 Detail, contrlr, Notification: AwakeNodesQueried

BendedArrow · May 29, 2017, 7:51am

That log looks fine…Node2 looks like a battery powered device. When you start up HA, does anything show up in the Zwave panel?

vincen · May 29, 2017, 8:53am

Well I made additional tests and realised range of ZWave in my system is really short I expected it to work better than just 2/3m inside
Here is what I have now in my system after re-adding devices correctly:

I have well 5 devices listed but I have physically only 4 devices (a wall plug, a multi-measure smoke sensor, a move/temperature/PIR sensor, a remote). Is it possible that a same device be added by mistake two times ??
Why does it display just the N logo or zzzz instead of a real name of devices ? as it makes it really tricky to know what is what…
I see well my wall switch that I can control without problem and also power consumption on it !

It displays me also all values handled by these sensons (going to spend few minutes to put them some friendly names ! Is it normal that the remote (Fibaro 6 buttons basic remote) doesn’t appear anywhere ?

Side question: how to setup security key ?? I have created a zwave_device_config.yaml at root of homeassistant setup but I still get this error in zwave logs:

2017-05-29 09:07:19.742 Always, OpenZwave Version 1.4.2508 Starting Up
2017-05-29 09:07:22.996 Info, Setting Up Provided Network Key for Secure Communications
2017-05-29 09:07:22.996 Warning, Failed - Network Key Not Set
2017-05-29 09:07:22.996 Info, mgr, Added driver for controller /dev/ttyACM1
2017-05-29 09:07:22.996 Info, Opening controller /dev/ttyACM1
2017-05-29 09:07:22.996 Info, Trying to open serial port /dev/ttyACM1 (attempt 1)
2017-05-29 09:07:22.996 Info, Serial port /dev/ttyACM1 opened (attempt 1)

Thanks,

Vincèn

BendedArrow · May 29, 2017, 9:06am

Before I give you any advice, do you have Open Zwave control panel working?

Tinkerer · May 29, 2017, 9:09am

See the Z-Wave documentation.

The missing names may well be cleared by restarting HA. For some reason the names don’t come in right away.

vincen · May 29, 2017, 9:43am

@BendedArrow If you mean the ZWave section appears in left pane in HA, and if I can access it, yep for sure
@Tinkerer Right for names (y) Restarted HA and now all real names of ZWave devices appear For Z-Wave documentation I already checked but it doesn’t work ! I created a zwave_device_config in my HA home directory of virtalenv but it doesn’t work ! I suspect Open ZWave expects that file somewhere else, still looking for that… Update on that point: I added in configuration file of HA config_path to indicate full access at my configuration file for OZW but then HA doesn’t start ZWave anymore

Tinkerer · May 29, 2017, 2:01pm

The key goes in options.xml.

As for not starting, there will be errors in the HA log (if you’re using systemd then probably viewable with journalctl -f -u home-assistant). With those errors we can help you, without them all anybody can do is suggest you undo the changes you made.

vincen · May 29, 2017, 2:26pm

Found where the original options.xml file was so I copied it over my HA main directory and now I don’t get anymore the error about security and all my paired devices have disappeared which is normal I guess now that security is active (have to pair them all again I guess
Thanks

BendedArrow · May 29, 2017, 3:32pm

Only the devices that you paired with Add Node Secure would not function, really. If you did not add any devices securely, simply putting a key it should allow devices that were there before to function… No devices should have “disappeared”.