Commands dropping after a few interactions

Hi All,

New to z-wave, using the z-wave integration (setup with a key) on the latest HASS.io install (on Ubuntu 16.04 LTS). My USB is set-up using the /dev/serial/by-id/device-xxxxx

My logs look healthy on boot - see below

2019-12-28 11:17:17.886 Always, OpenZwave Version 1.4.3440 Starting Up
2019-12-28 11:18:10.464 Info, Setting Up Provided Network Key for Secure Communications
2019-12-28 11:18:10.464 Info, mgr,     Added driver for controller /dev/serial/by-id/usb-0658_0200-if00
2019-12-28 11:18:10.465 Info,   Opening controller /dev/serial/by-id/usb-0658_0200-if00
2019-12-28 11:18:10.465 Info, Trying to open serial port /dev/serial/by-id/usb-0658_0200-if00 (attempt 1)
2019-12-28 11:18:10.465 Info, Serial port /dev/serial/by-id/usb-0658_0200-if00 opened (attempt 1)
2019-12-28 11:18:10.465 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-12-28 11:18:10.465 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2019-12-28 11:18:10.465 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2019-12-28 11:18:10.465 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2019-12-28 11:18:10.465 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2019-12-28 11:18:10.465 Detail, 
2019-12-28 11:18:10.465 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-12-28 11:18:10.467 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x35, 0x34, 0x00, 0x01, 0x93
2019-12-28 11:18:10.467 Detail, 
2019-12-28 11:18:10.467 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2019-12-28 11:18:10.467 Info, contrlr,     Static Controller library, version Z-Wave 4.54
2019-12-28 11:18:10.467 Detail, Node045,   Expected reply was received
2019-12-28 11:18:10.467 Detail, Node045,   Message transaction complete
2019-12-28 11:18:10.467 Detail, 
2019-12-28 11:18:10.467 Detail, contrlr, Removing current message
2019-12-28 11:18:10.467 Detail, 
2019-12-28 11:18:10.467 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2019-12-28 11:18:10.469 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xcf, 0x51, 0xea, 0x1c, 0x01, 0xbf
2019-12-28 11:18:10.469 Detail, 
2019-12-28 11:18:10.469 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xcf51ea1c.  Our node ID = 1
2019-12-28 11:18:10.469 Detail, Node081,   Expected reply was received
2019-12-28 11:18:10.469 Detail, Node081,   Message transaction complete
2019-12-28 11:18:10.469 Detail, 
2019-12-28 11:18:10.469 Detail, contrlr, Removing current message
2019-12-28 11:18:10.469 Detail, 
2019-12-28 11:18:10.469 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2019-12-28 11:18:10.471 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x08, 0xf7
2019-12-28 11:18:10.471 Detail, 
2019-12-28 11:18:10.471 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2019-12-28 11:18:10.471 Info, contrlr,     There is no SUC ID Server (SIS) in this network.
2019-12-28 11:18:10.471 Info, contrlr,     The PC controller is a primary controller.
2019-12-28 11:18:10.471 Detail, Node247,   Expected reply was received
2019-12-28 11:18:10.471 Detail, Node247,   Message transaction complete
2019-12-28 11:18:10.471 Detail, 
2019-12-28 11:18:10.471 Detail, contrlr, Removing current message
2019-12-28 11:18:10.471 Detail, 
2019-12-28 11:18:10.471 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2019-12-28 11:18:10.474 Detail, contrlr,   Received: 0x01, 0x2b, 0x01, 0x07, 0x01, 0x01, 0x00, 0x86, 0x02, 0x01, 0x00, 0x5a, 0xfe, 0x81, 0xff, 0x88, 0x4f, 0x1f, 0x00, 0x00, 0xfb, 0x9f, 0x7d, 0xa0, 0x67, 0x00, 0x00, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xe8, 0x73, 0x00, 0x00, 0x0e, 0x00, 0x00, 0x60, 0x00, 0x00, 0xf8
2019-12-28 11:18:10.474 Detail, 
2019-12-28 11:18:10.474 Info, contrlr,  Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2019-12-28 11:18:10.474 Info, contrlr,     Serial API Version:   1.1
2019-12-28 11:18:10.474 Info, contrlr,     Manufacturer ID:      0x0086
2019-12-28 11:18:10.474 Info, contrlr,     Product Type:         0x0201
2019-12-28 11:18:10.474 Info, contrlr,     Product ID:           0x005a
2019-12-28 11:18:10.474 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2019-12-28 11:18:10.474 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2019-12-28 11:18:10.474 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2019-12-28 11:18:10.474 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2019-12-28 11:18:10.474 Detail, Node001,   Expected reply was received
2019-12-28 11:18:10.474 Detail, Node001,   Message transaction complete
2019-12-28 11:18:10.474 Detail, 
2019-12-28 11:18:10.474 Detail, contrlr, Removing current message
2019-12-28 11:18:10.474 Detail, 
2019-12-28 11:18:10.474 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2019-12-28 11:18:10.476 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2019-12-28 11:18:10.476 Detail, 
2019-12-28 11:18:10.476 Info, contrlr, Received reply to GET_SUC_NODE_ID.  Node ID = 0
2019-12-28 11:18:10.476 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node
2019-12-28 11:18:10.476 Detail, Node172,   Expected reply was received
2019-12-28 11:18:10.476 Detail, Node172,   Message transaction complete

After a lot of logs I ultimately get the query complete:

2019-12-28 11:18:28.614 Detail, Node007, Notification: NodeQueriesComplete
2019-12-28 11:18:28.615 Detail, Node009, Query Stage Complete (Dynamic)
2019-12-28 11:18:28.615 Detail, Node009, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-12-28 11:18:28.615 Detail, Node009, QueryStage_Configuration
2019-12-28 11:18:28.615 Detail, Node009, QueryStage_Complete
2019-12-28 11:18:28.615 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2019-12-28 11:18:28.615 Warning, CheckCompletedNodeQueries all=1, deadFound=0 sleepingOnly=1
2019-12-28 11:18:28.615 Info,          Node query processing complete.
2019-12-28 11:18:28.615 Detail, Node009, Notification: NodeQueriesComplete
2019-12-28 11:18:28.615 Detail, contrlr, Notification: AllNodesQueried

After a minute or so I get a series of errors. Sometimes I can execute a command or two on my setup and other times none at all. It doesn’t seem to be a specific node that I query causing the issues.

2019-12-28 11:20:33.437 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - False
2019-12-28 11:20:33.437 Info, Node009, SwitchBinary::Set - Setting node 9 to Off
2019-12-28 11:20:33.437 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x45, 0xc5
2019-12-28 11:20:33.437 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x46, 0xc7
2019-12-28 11:20:33.437 Detail, 
2019-12-28 11:20:33.437 Info, Node009, Sending (Send) message (Callback ID=0x45, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x45, 0xc5
2019-12-28 11:20:34.437 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-28 11:20:34.437 Detail, Node009, Removing current message
2019-12-28 11:20:34.437 Detail, Node009, Notification: Notification - TimeOut
2019-12-28 11:20:34.438 Detail, 
2019-12-28 11:20:34.438 Info, Node009, Sending (Send) message (Callback ID=0x46, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x46, 0xc7
2019-12-28 11:20:35.438 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-28 11:20:35.439 Detail, Node009, Removing current message
2019-12-28 11:20:35.439 Detail, Node009, Notification: Notification - TimeOut

Any and all help on how to stop it dropping out would be much appreciated as my whole house has these and i need to tell it what light switch type so I can use my switches (my wife is a little annoyed)

How many devices do you have and what is Node-009?

I have 4 devices currently connected:
Node 7: aeotec nano dimmer
Node 9: aeotec dual nano switch
Node 1: the z-wave stock
Node 6: garage controller

I’ve got three offline nodes which are the same style as node 7 and 9. These are offline as they are not in use. I healed the network post removing them.

I have a few more nodes but I haven’t added them as it seems to be problematic.

I’ve had this issue form prior to the node removal. The nodes were removed as the electrician is changing the light switch type so they were only in temporarily when I connected them.

I’m tempted to factory reset everything and start again.

I’ve tried a few items with no luck, once the system is up and finishes doing a node check it errors.

I’m only using one brand of z-wave devices, aeotec.

I paired them using the stick directly (not bass), does that cause any issues??

How far apart are these devices and what type of wall construction?

right now my server is on the ground floor with the devices on the top floor.

The construction is a new home with all dry wall / timber frame. By distance they are:

  • direct (ie. shortest distance through walls): 6-10m (server with z-wave stick is directly below
  • by open air (ie: avoiding walls, as I can walk the path): 20-25m

When I reset the device, I can control the existing units for a few steps and the avg response time is excellent (attaching a photo of hass device outcomes).

I can connect more devices to reduce the distance to the closest device. I’ve got a aeotec garage controller which plugs into a power point. I’ll plug that very close to the device and see if it works whilst the rest have timed out.

I plugged in my garage door controller within 2m of the server running HASS.io with the z-wave USB connected.

My logs attempt to query node 6 (closest node, the garage controller first). I times out mid-way through sending/receiving status updates on that node.

2019-12-30 08:33:42.727 Info, Node006, Sending (Query) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x06, 0x0a, 0x98, 0x80, 0xa7, 0xcc, 0x64, 0x2b, 0x67, 0x78, 0x88, 0xed, 0x05, 0x01, 0xb3:
2019-12-30 08:33:42.735 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 08:33:42.735 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 08:33:42.754 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x03, 0xe9
2019-12-30 08:33:42.754 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2019-12-30 08:33:42.754 Info, Node006, Request RTT 108 Average Request RTT 83
2019-12-30 08:33:42.775 Detail, Node006,   Received: 0x01, 0x1e, 0x00, 0x04, 0x00, 0x06, 0x18, 0x98, 0x81, 0x1b, 0xa7, 0x24, 0xd7, 0x7b, 0xd3, 0x11, 0x1a, 0x51, 0x71, 0xb3, 0x9a, 0xdb, 0xa7, 0x2c, 0x04, 0x76, 0x99, 0x58, 0x12, 0xd7, 0xe1, 0xc0
2019-12-30 08:33:42.775 Info, Raw: 0x98, 0x81, 0x1b, 0xa7, 0x24, 0xd7, 0x7b, 0xd3, 0x11, 0x1a, 0x51, 0x71, 0xb3, 0x9a, 0xdb, 0xa7, 0x2c, 0x04, 0x76, 0x99, 0x58, 0x12, 0xd7, 0xe1, 0xc0
2019-12-30 08:33:42.775 Detail, Node006, Decrypted Packet: 0x00, 0x73, 0x03, 0x00, 0x00
2019-12-30 08:33:42.775 Detail, 
2019-12-30 08:33:42.775 Info, Node006, Response RTT 130 Average Response RTT 130
2019-12-30 08:33:42.775 Info, Node006, Received a PowerLevel report: PowerLevel=Normal, Timeout=0
2019-12-30 08:33:42.775 Detail, Node006, Initial read of value
2019-12-30 08:33:42.775 Detail, Node006, Initial read of value
2019-12-30 08:33:42.775 Detail, Node006,   Expected reply and command class was received
2019-12-30 08:33:42.775 Detail, Node006,   Message transaction complete
2019-12-30 08:33:42.775 Detail, 
2019-12-30 08:33:42.775 Detail, Node006, Removing current message
2019-12-30 08:33:42.775 Detail, Node006, Notification: ValueChanged
2019-12-30 08:33:42.777 Detail, Node006, Notification: ValueChanged
2019-12-30 08:33:42.779 Detail, Node006, Query Stage Complete (Session)
2019-12-30 08:33:42.779 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2019-12-30 08:33:42.779 Detail, Node006, QueryStage_Dynamic
2019-12-30 08:33:42.779 Detail, Node006, Queuing (Send) BasicCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x20, 0x02, 0x25, 0x25, 0xc3
2019-12-30 08:33:42.779 Detail, Node006, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 08:33:42.779 Detail, Node006, Queuing (Send) SwitchBinaryCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x25, 0x02, 0x25, 0x26, 0xc5
2019-12-30 08:33:42.779 Detail, Node006, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_BARRIER_OPERATOR
2019-12-30 08:33:42.779 Detail, Node006, Queuing (Send) BarrierOperatorCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x66, 0x02, 0x25, 0x27, 0x87
2019-12-30 08:33:42.779 Info, Node006, AlarmCmd_Get Not Supported on this node
2019-12-30 08:33:42.779 Detail, Node006, Queuing (Query) Query Stage Complete (Dynamic)
2019-12-30 08:33:42.779 Detail, 
2019-12-30 08:33:42.779 Info, Node006, Sending (Send) message (Callback ID=0x25, Expected Reply=0x04) - BasicCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x20, 0x02, 0x25, 0x25, 0xc3
2019-12-30 08:33:42.786 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 08:33:42.786 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 08:33:42.803 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x25, 0x00, 0x00, 0x02, 0xcc
2019-12-30 08:33:42.803 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x25 received (expected 0x25)
2019-12-30 08:33:42.803 Info, Node006, Request RTT 23 Average Request RTT 53
2019-12-30 08:33:42.803 Detail,   Expected callbackId was received
2019-12-30 08:33:52.780 Error, Node006, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 08:33:52.780 Detail, Node006, Removing current message
2019-12-30 08:33:52.780 Detail, Node006, Notification: Notification - TimeOut
2019-12-30 08:33:52.781 Detail, 
2019-12-30 08:33:52.781 Info, Node006, Processing (Send) Nonce Request message (Callback ID=0x26, Expected Reply=0x04)
2019-12-30 08:33:52.781 Info, Node006, Sending (Send) message (Callback ID=0x26, Expected Reply=0x04) - Nonce_Get(SwitchBinaryCmd_Get) - 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x98, 0x40, 0x05, 0x02:
2019-12-30 08:33:53.781 Error, Node006, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 08:33:53.781 Detail, Node006, Removing current message
2019-12-30 08:33:53.781 Detail, Node006, Notification: Notification - TimeOut
2019-12-30 08:33:53.782 Detail, 
2019-12-30 08:33:53.782 Info, Node006, Processing (Send) Nonce Request message (Callback ID=0x27, Expected Reply=0x04)
2019-12-30 08:33:53.782 Info, Node006, Sending (Send) message (Callback ID=0x27, Expected Reply=0x04) - Nonce_Get(BarrierOperatorCmd_Get) - 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x98, 0x40, 0x05, 0x02:
2019-12-30 08:33:54.782 Error, Node006, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 08:33:54.782 Detail, Node006, Removing current message
2019-12-30 08:33:54.782 Detail, Node006, Notification: Notification - TimeOut

If i understand this correctly, it connects initially, device reports backs (e.g. power level) and then starts to time-out.

Now I am more confused!

Update: Turned off the bad node (node 6, garage door) and restarted the system.

All nodes checked in correctly and reported back for the entire log. I then attempted to send an on/off command to a switch which failed.

Full restart log showing working check-in with error on first manual interaction.

2019-12-30 08:46:28.131 Info, Node009, Sending (Send) message (Callback ID=0x37, Expected Reply=0x04) - AlarmCmd_Get (Node=9): 0x01, 0x0c, 0x00, 0x13, 0x09, 0x05, 0x71, 0x04, 0x00, 0x04, 0x01, 0x25, 0x37, 0x8e
2019-12-30 08:46:28.138 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 08:46:28.138 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 08:46:28.155 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x37, 0x00, 0x00, 0x02, 0xde
2019-12-30 08:46:28.155 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x37 received (expected 0x37)
2019-12-30 08:46:28.155 Info, Node009, Request RTT 24 Average Request RTT 24
2019-12-30 08:46:28.155 Detail,   Expected callbackId was received
2019-12-30 08:46:28.167 Detail, Node009,   Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x09, 0x09, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x04, 0xfe, 0x00, 0x85
2019-12-30 08:46:28.167 Detail, 
2019-12-30 08:46:28.167 Info, Node009, Response RTT 36 Average Response RTT 36
2019-12-30 08:46:28.167 Info, Node009, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Heat event:254, status=255
2019-12-30 08:46:28.167 Detail, Node009, Initial read of value
2019-12-30 08:46:28.167 Detail, Node009, Initial read of value
2019-12-30 08:46:28.167 Detail, Node009, Initial read of value
2019-12-30 08:46:28.167 Detail, Node009, Initial read of value
2019-12-30 08:46:28.167 Detail, Node009,   Expected reply and command class was received
2019-12-30 08:46:28.167 Detail, Node009,   Message transaction complete
2019-12-30 08:46:28.167 Detail, 
2019-12-30 08:46:28.167 Detail, Node009, Removing current message
2019-12-30 08:46:28.167 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.169 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.170 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.171 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.172 Detail, 
2019-12-30 08:46:28.172 Info, Node009, Sending (Send) message (Callback ID=0x38, Expected Reply=0x04) - AlarmCmd_Get (Node=9): 0x01, 0x0c, 0x00, 0x13, 0x09, 0x05, 0x71, 0x04, 0x00, 0x08, 0x01, 0x25, 0x38, 0x8d
2019-12-30 08:46:28.180 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 08:46:28.180 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 08:46:28.197 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x38, 0x00, 0x00, 0x02, 0xd1
2019-12-30 08:46:28.197 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x38 received (expected 0x38)
2019-12-30 08:46:28.197 Info, Node009, Request RTT 24 Average Request RTT 24
2019-12-30 08:46:28.197 Detail,   Expected callbackId was received
2019-12-30 08:46:28.211 Detail, Node009,   Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x09, 0x09, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x08, 0xfe, 0x00, 0x89
2019-12-30 08:46:28.211 Detail, 
2019-12-30 08:46:28.211 Info, Node009, Response RTT 38 Average Response RTT 37
2019-12-30 08:46:28.211 Info, Node009, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Power Management event:254, status=255
2019-12-30 08:46:28.211 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2019-12-30 08:46:28.211 Detail, Node009, Changes to this value are not verified
2019-12-30 08:46:28.211 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2019-12-30 08:46:28.211 Detail, Node009, Changes to this value are not verified
2019-12-30 08:46:28.211 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2019-12-30 08:46:28.211 Detail, Node009, Changes to this value are not verified
2019-12-30 08:46:28.211 Detail, Node009, Initial read of value
2019-12-30 08:46:28.211 Detail, Node009,   Expected reply and command class was received
2019-12-30 08:46:28.211 Detail, Node009,   Message transaction complete
2019-12-30 08:46:28.211 Detail, 
2019-12-30 08:46:28.211 Detail, Node009, Removing current message
2019-12-30 08:46:28.212 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.213 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.215 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.216 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.218 Detail, 
2019-12-30 08:46:28.218 Info, Node009, Sending (Send) message (Callback ID=0x39, Expected Reply=0x04) - ClockCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x81, 0x05, 0x25, 0x39, 0x76
2019-12-30 08:46:28.225 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 08:46:28.225 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 08:46:28.241 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x39, 0x00, 0x00, 0x02, 0xd0
2019-12-30 08:46:28.241 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x39 received (expected 0x39)
2019-12-30 08:46:28.242 Info, Node009, Request RTT 23 Average Request RTT 23
2019-12-30 08:46:28.242 Detail,   Expected callbackId was received
2019-12-30 08:46:28.258 Detail, Node009,   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x09, 0x04, 0x81, 0x06, 0x0e, 0x24, 0x51
2019-12-30 08:46:28.258 Detail, 
2019-12-30 08:46:28.258 Info, Node009, Response RTT 39 Average Response RTT 38
2019-12-30 08:46:28.258 Info, Node009, Received Clock report: Invalid 14:36
2019-12-30 08:46:28.258 Detail, Node009, Initial read of value
2019-12-30 08:46:28.258 Detail, Node009, Initial read of value
2019-12-30 08:46:28.258 Detail, Node009,   Expected reply and command class was received
2019-12-30 08:46:28.258 Detail, Node009,   Message transaction complete
2019-12-30 08:46:28.258 Detail, 
2019-12-30 08:46:28.258 Detail, Node009, Removing current message
2019-12-30 08:46:28.258 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.260 Detail, Node009, Notification: ValueChanged
2019-12-30 08:46:28.262 Detail, Node007, Query Stage Complete (Dynamic)
2019-12-30 08:46:28.262 Detail, Node007, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-12-30 08:46:28.262 Detail, Node007, QueryStage_Configuration
2019-12-30 08:46:28.262 Detail, Node007, QueryStage_Complete
2019-12-30 08:46:28.262 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2019-12-30 08:46:28.262 Warning, CheckCompletedNodeQueries all=0, deadFound=1 sleepingOnly=0
2019-12-30 08:46:28.262 Detail, Node007, Notification: NodeQueriesComplete
2019-12-30 08:46:28.263 Detail, Node009, Query Stage Complete (Dynamic)
2019-12-30 08:46:28.263 Detail, Node009, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-12-30 08:46:28.263 Detail, Node009, QueryStage_Configuration
2019-12-30 08:46:28.263 Detail, Node009, QueryStage_Complete
2019-12-30 08:46:28.263 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2019-12-30 08:46:28.263 Warning, CheckCompletedNodeQueries all=1, deadFound=1 sleepingOnly=1
2019-12-30 08:46:28.263 Info,          Node query processing complete except for dead nodes.
2019-12-30 08:46:28.263 Detail, Node009, Notification: NodeQueriesComplete
2019-12-30 08:46:28.263 Detail, contrlr, Notification: AllNodesQueriedSomeDead
2019-12-30 08:52:50.127 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - False
2019-12-30 08:52:50.127 Info, Node009, SwitchBinary::Set - Setting node 9 to Off
2019-12-30 08:52:50.127 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x3a, 0xba
2019-12-30 08:52:50.127 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3b, 0xba
2019-12-30 08:52:50.127 Detail, 
2019-12-30 08:52:50.127 Info, Node009, Sending (Send) message (Callback ID=0x3a, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x3a, 0xba
2019-12-30 08:52:51.127 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 08:52:51.127 Detail, Node009, Removing current message
2019-12-30 08:52:51.127 Detail, Node009, Notification: Notification - TimeOut
2019-12-30 08:52:51.128 Detail, 
2019-12-30 08:52:51.128 Info, Node009, Sending (Send) message (Callback ID=0x3b, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3b, 0xba
2019-12-30 08:52:52.128 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 08:52:52.128 Detail, Node009, Removing current message
2019-12-30 08:52:52.128 Detail, Node009, Notification: Notification - TimeOut

After more digging, I can confirm that I can correctly interact with a device for a few minutes

Timeline

  • 10:07:31 : devices all completed check-in post reboot
  • in-between: able to control the on/off of node 9, i did notice that the state stops updating correctly as I interacted with it more frequently
  • 10:10:53 : first interaction timeout (all I did was as above)

I tried this on node 7 and had the exact same outcome.

2019-12-30 10:07:31.635 Detail, Node009, Notification: NodeQueriesComplete
2019-12-30 10:07:31.635 Detail, contrlr, Notification: AllNodesQueriedSomeDead
2019-12-30 10:07:55.738 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - True
2019-12-30 10:07:55.738 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2019-12-30 10:07:55.738 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x3a, 0x45
2019-12-30 10:07:55.738 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3b, 0xba
2019-12-30 10:07:55.738 Detail, 
2019-12-30 10:07:55.738 Info, Node009, Sending (Send) message (Callback ID=0x3a, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x3a, 0x45
2019-12-30 10:07:55.745 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:07:55.746 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:07:55.762 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x3a, 0x00, 0x00, 0x02, 0xd3
2019-12-30 10:07:55.762 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x3a received (expected 0x3a)
2019-12-30 10:07:55.762 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:07:55.762 Detail,   Expected callbackId was received
2019-12-30 10:07:55.762 Detail,   Expected reply was received
2019-12-30 10:07:55.762 Detail,   Message transaction complete
2019-12-30 10:07:55.762 Detail, 
2019-12-30 10:07:55.762 Detail, Node009, Removing current message
2019-12-30 10:07:55.762 Detail, 
2019-12-30 10:07:55.762 Info, Node009, Sending (Send) message (Callback ID=0x3b, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3b, 0xba
2019-12-30 10:07:55.770 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:07:55.770 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:07:55.787 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x3b, 0x00, 0x00, 0x02, 0xd2
2019-12-30 10:07:55.787 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x3b received (expected 0x3b)
2019-12-30 10:07:55.787 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:07:55.787 Detail,   Expected callbackId was received
2019-12-30 10:07:55.798 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0x00, 0xb3
2019-12-30 10:07:55.798 Detail, 
2019-12-30 10:07:55.798 Info, Node009, Response RTT 36 Average Response RTT 36
2019-12-30 10:07:55.798 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:07:55.798 Info, Node009, Received SwitchBinary report from node 9: level=Off
2019-12-30 10:07:55.798 Detail, Node009, Refreshed Value: old value=false, new value=false, type=bool
2019-12-30 10:07:55.798 Detail, Node009, Changes to this value are not verified
2019-12-30 10:07:55.798 Detail, Node009,   Expected reply and command class was received
2019-12-30 10:07:55.798 Detail, Node009,   Message transaction complete
2019-12-30 10:07:55.798 Detail, 
2019-12-30 10:07:55.799 Detail, Node009, Removing current message
2019-12-30 10:07:55.799 Detail, Node009, Notification: ValueChanged
2019-12-30 10:08:05.070 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - True
2019-12-30 10:08:05.070 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2019-12-30 10:08:05.070 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x3c, 0x43
2019-12-30 10:08:05.071 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3d, 0xbc
2019-12-30 10:08:05.075 Detail, 
2019-12-30 10:08:05.075 Info, Node009, Sending (Send) message (Callback ID=0x3c, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x3c, 0x43
2019-12-30 10:08:05.083 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:08:05.083 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:08:05.100 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x3c, 0x00, 0x00, 0x03, 0xd4
2019-12-30 10:08:05.100 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x3c received (expected 0x3c)
2019-12-30 10:08:05.100 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:08:05.100 Detail,   Expected callbackId was received
2019-12-30 10:08:05.100 Detail,   Expected reply was received
2019-12-30 10:08:05.100 Detail,   Message transaction complete
2019-12-30 10:08:05.100 Detail, 
2019-12-30 10:08:05.100 Detail, Node009, Removing current message
2019-12-30 10:08:05.100 Detail, 
2019-12-30 10:08:05.100 Info, Node009, Sending (Send) message (Callback ID=0x3d, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3d, 0xbc
2019-12-30 10:08:05.108 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:08:05.108 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:08:05.124 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x3d, 0x00, 0x00, 0x02, 0xd4
2019-12-30 10:08:05.124 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x3d received (expected 0x3d)
2019-12-30 10:08:05.124 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:08:05.124 Detail,   Expected callbackId was received
2019-12-30 10:08:05.136 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0xff, 0x4c
2019-12-30 10:08:05.136 Detail, 
2019-12-30 10:08:05.136 Info, Node009, Response RTT 36 Average Response RTT 36
2019-12-30 10:08:05.136 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:08:05.136 Info, Node009, Received SwitchBinary report from node 9: level=On
2019-12-30 10:08:05.136 Detail, Node009, Refreshed Value: old value=false, new value=true, type=bool
2019-12-30 10:08:05.136 Detail, Node009, Changes to this value are not verified
2019-12-30 10:08:05.136 Detail, Node009,   Expected reply and command class was received
2019-12-30 10:08:05.136 Detail, Node009,   Message transaction complete
2019-12-30 10:08:05.136 Detail, 
2019-12-30 10:08:05.136 Detail, Node009, Removing current message
2019-12-30 10:08:05.136 Detail, Node009, Notification: ValueChanged
2019-12-30 10:08:05.554 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - False
2019-12-30 10:08:05.554 Info, Node009, SwitchBinary::Set - Setting node 9 to Off
2019-12-30 10:08:05.554 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x3e, 0xbe
2019-12-30 10:08:05.554 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3f, 0xbe
2019-12-30 10:08:05.554 Detail, 
2019-12-30 10:08:05.554 Info, Node009, Sending (Send) message (Callback ID=0x3e, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x3e, 0xbe
2019-12-30 10:08:05.562 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:08:05.563 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:08:05.579 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x3e, 0x00, 0x00, 0x02, 0xd7
2019-12-30 10:08:05.579 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x3e received (expected 0x3e)
2019-12-30 10:08:05.579 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:08:05.579 Detail,   Expected callbackId was received
2019-12-30 10:08:05.579 Detail,   Expected reply was received
2019-12-30 10:08:05.579 Detail,   Message transaction complete
2019-12-30 10:08:05.579 Detail, 
2019-12-30 10:08:05.579 Detail, Node009, Removing current message
2019-12-30 10:08:05.579 Detail, 
2019-12-30 10:08:05.579 Info, Node009, Sending (Send) message (Callback ID=0x3f, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x3f, 0xbe
2019-12-30 10:08:05.587 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:08:05.587 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:08:05.603 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x3f, 0x00, 0x00, 0x02, 0xd6
2019-12-30 10:08:05.604 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x3f received (expected 0x3f)
2019-12-30 10:08:05.604 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:08:05.604 Detail,   Expected callbackId was received
2019-12-30 10:08:05.619 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0xff, 0x4c
2019-12-30 10:08:05.619 Detail, 
2019-12-30 10:08:05.619 Info, Node009, Response RTT 39 Average Response RTT 37
2019-12-30 10:08:05.619 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:08:05.619 Info, Node009, Received SwitchBinary report from node 9: level=On
2019-12-30 10:08:05.619 Detail, Node009, Refreshed Value: old value=true, new value=true, type=bool
2019-12-30 10:08:05.619 Detail, Node009, Changes to this value are not verified
2019-12-30 10:08:05.619 Detail, Node009,   Expected reply and command class was received
2019-12-30 10:08:05.619 Detail, Node009,   Message transaction complete
2019-12-30 10:08:05.619 Detail, 
2019-12-30 10:08:05.619 Detail, Node009, Removing current message
2019-12-30 10:08:05.619 Detail, Node009, Notification: ValueChanged
2019-12-30 10:08:05.673 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0xff, 0x4c
2019-12-30 10:08:05.673 Detail, 
2019-12-30 10:08:05.673 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:08:05.673 Info, Node009, Received SwitchBinary report from node 9: level=On
2019-12-30 10:08:05.673 Detail, Node009, Refreshed Value: old value=true, new value=true, type=bool
2019-12-30 10:08:05.673 Detail, Node009, Changes to this value are not verified
2019-12-30 10:08:05.673 Detail, Node009, Notification: ValueChanged
2019-12-30 10:08:23.120 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - False
2019-12-30 10:08:23.120 Info, Node009, SwitchBinary::Set - Setting node 9 to Off
2019-12-30 10:08:23.120 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x40, 0xc0
2019-12-30 10:08:23.120 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x41, 0xc0
2019-12-30 10:08:23.120 Detail, 
2019-12-30 10:08:23.120 Info, Node009, Sending (Send) message (Callback ID=0x40, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x40, 0xc0
2019-12-30 10:08:23.129 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:08:23.129 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:08:23.145 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x40, 0x00, 0x00, 0x02, 0xa9
2019-12-30 10:08:23.145 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x40 received (expected 0x40)
2019-12-30 10:08:23.145 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:08:23.145 Detail,   Expected callbackId was received
2019-12-30 10:08:23.145 Detail,   Expected reply was received
2019-12-30 10:08:23.145 Detail,   Message transaction complete
2019-12-30 10:08:23.145 Detail, 
2019-12-30 10:08:23.145 Detail, Node009, Removing current message
2019-12-30 10:08:23.145 Detail, 
2019-12-30 10:08:23.145 Info, Node009, Sending (Send) message (Callback ID=0x41, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x41, 0xc0
2019-12-30 10:08:23.153 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:08:23.153 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:08:23.170 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x41, 0x00, 0x00, 0x02, 0xa8
2019-12-30 10:08:23.170 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x41 received (expected 0x41)
2019-12-30 10:08:23.170 Info, Node009, Request RTT 24 Average Request RTT 23
2019-12-30 10:08:23.170 Detail,   Expected callbackId was received
2019-12-30 10:08:23.216 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0x00, 0xb3
2019-12-30 10:08:23.216 Detail, 
2019-12-30 10:08:23.216 Info, Node009, Response RTT 70 Average Response RTT 53
2019-12-30 10:08:23.216 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:08:23.216 Info, Node009, Received SwitchBinary report from node 9: level=Off
2019-12-30 10:08:23.216 Detail, Node009, Refreshed Value: old value=true, new value=false, type=bool
2019-12-30 10:08:23.216 Detail, Node009, Changes to this value are not verified
2019-12-30 10:08:23.216 Detail, Node009,   Expected reply and command class was received
2019-12-30 10:08:23.216 Detail, Node009,   Message transaction complete
2019-12-30 10:08:23.217 Detail, 
2019-12-30 10:08:23.217 Detail, Node009, Removing current message
2019-12-30 10:08:23.217 Detail, Node009, Notification: ValueChanged
2019-12-30 10:08:27.671 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - True
2019-12-30 10:08:27.671 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2019-12-30 10:08:27.671 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x42, 0x3d
2019-12-30 10:08:27.671 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x43, 0xc2
2019-12-30 10:08:27.671 Detail, 
2019-12-30 10:08:27.671 Info, Node009, Sending (Send) message (Callback ID=0x42, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x42, 0x3d
2019-12-30 10:08:27.679 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:08:27.679 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:08:27.733 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x42, 0x00, 0x00, 0x06, 0xaf
2019-12-30 10:08:27.733 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x42 received (expected 0x42)
2019-12-30 10:08:27.733 Info, Node009, Request RTT 61 Average Request RTT 42
2019-12-30 10:08:27.733 Detail,   Expected callbackId was received
2019-12-30 10:08:27.733 Detail,   Expected reply was received
2019-12-30 10:08:27.733 Detail,   Message transaction complete
2019-12-30 10:08:27.733 Detail, 
2019-12-30 10:08:27.733 Detail, Node009, Removing current message


< removed some messages of me switching on / off for message length >


2019-12-30 10:09:46.869 Detail, Node009, Notification: ValueChanged
2019-12-30 10:09:47.323 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - True
2019-12-30 10:09:47.323 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2019-12-30 10:09:47.323 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x4a, 0x35
2019-12-30 10:09:47.323 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x4b, 0xca
2019-12-30 10:09:47.323 Detail, 
2019-12-30 10:09:47.323 Info, Node009, Sending (Send) message (Callback ID=0x4a, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x4a, 0x35
2019-12-30 10:09:47.331 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:09:47.331 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:09:47.348 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4a, 0x00, 0x00, 0x03, 0xa2
2019-12-30 10:09:47.348 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4a received (expected 0x4a)
2019-12-30 10:09:47.348 Info, Node009, Request RTT 25 Average Request RTT 24
2019-12-30 10:09:47.348 Detail,   Expected callbackId was received
2019-12-30 10:09:47.348 Detail,   Expected reply was received
2019-12-30 10:09:47.348 Detail,   Message transaction complete
2019-12-30 10:09:47.348 Detail, 
2019-12-30 10:09:47.348 Detail, Node009, Removing current message
2019-12-30 10:09:47.348 Detail, 
2019-12-30 10:09:47.348 Info, Node009, Sending (Send) message (Callback ID=0x4b, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x4b, 0xca
2019-12-30 10:09:47.356 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:09:47.356 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:09:47.373 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4b, 0x00, 0x00, 0x02, 0xa2
2019-12-30 10:09:47.373 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4b received (expected 0x4b)
2019-12-30 10:09:47.373 Info, Node009, Request RTT 24 Average Request RTT 24
2019-12-30 10:09:47.373 Detail,   Expected callbackId was received
2019-12-30 10:09:47.384 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0x00, 0xb3
2019-12-30 10:09:47.385 Detail, 
2019-12-30 10:09:47.385 Info, Node009, Response RTT 36 Average Response RTT 37
2019-12-30 10:09:47.385 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:09:47.385 Info, Node009, Received SwitchBinary report from node 9: level=Off
2019-12-30 10:09:47.385 Detail, Node009, Refreshed Value: old value=false, new value=false, type=bool
2019-12-30 10:09:47.385 Detail, Node009, Changes to this value are not verified
2019-12-30 10:09:47.385 Detail, Node009,   Expected reply and command class was received
2019-12-30 10:09:47.385 Detail, Node009,   Message transaction complete
2019-12-30 10:09:47.385 Detail, 
2019-12-30 10:09:47.385 Detail, Node009, Removing current message
2019-12-30 10:09:47.385 Detail, Node009, Notification: ValueChanged
2019-12-30 10:09:56.547 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - True
2019-12-30 10:09:56.547 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2019-12-30 10:09:56.547 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x4c, 0x33
2019-12-30 10:09:56.548 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x4d, 0xcc
2019-12-30 10:09:56.548 Detail, 
2019-12-30 10:09:56.548 Info, Node009, Sending (Send) message (Callback ID=0x4c, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x4c, 0x33
2019-12-30 10:09:56.556 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:09:56.556 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:09:56.572 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4c, 0x00, 0x00, 0x02, 0xa5
2019-12-30 10:09:56.572 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4c received (expected 0x4c)
2019-12-30 10:09:56.573 Info, Node009, Request RTT 24 Average Request RTT 24
2019-12-30 10:09:56.573 Detail,   Expected callbackId was received
2019-12-30 10:09:56.573 Detail,   Expected reply was received
2019-12-30 10:09:56.573 Detail,   Message transaction complete
2019-12-30 10:09:56.573 Detail, 
2019-12-30 10:09:56.573 Detail, Node009, Removing current message
2019-12-30 10:09:56.573 Detail, 
2019-12-30 10:09:56.573 Info, Node009, Sending (Send) message (Callback ID=0x4d, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x4d, 0xcc
2019-12-30 10:09:56.581 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:09:56.581 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:09:56.613 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4d, 0x00, 0x00, 0x04, 0xa2
2019-12-30 10:09:56.613 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4d received (expected 0x4d)
2019-12-30 10:09:56.613 Info, Node009, Request RTT 40 Average Request RTT 32
2019-12-30 10:09:56.613 Detail,   Expected callbackId was received
2019-12-30 10:09:56.625 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0xff, 0x4c
2019-12-30 10:09:56.625 Detail, 
2019-12-30 10:09:56.625 Info, Node009, Response RTT 52 Average Response RTT 44
2019-12-30 10:09:56.626 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:09:56.626 Info, Node009, Received SwitchBinary report from node 9: level=On
2019-12-30 10:09:56.626 Detail, Node009, Refreshed Value: old value=false, new value=true, type=bool
2019-12-30 10:09:56.626 Detail, Node009, Changes to this value are not verified
2019-12-30 10:09:56.626 Detail, Node009,   Expected reply and command class was received
2019-12-30 10:09:56.626 Detail, Node009,   Message transaction complete
2019-12-30 10:09:56.626 Detail, 
2019-12-30 10:09:56.626 Detail, Node009, Removing current message
2019-12-30 10:09:56.626 Detail, Node009, Notification: ValueChanged
2019-12-30 10:09:59.428 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - False
2019-12-30 10:09:59.428 Info, Node009, SwitchBinary::Set - Setting node 9 to Off
2019-12-30 10:09:59.428 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x4e, 0xce
2019-12-30 10:09:59.428 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x4f, 0xce
2019-12-30 10:09:59.428 Detail, 
2019-12-30 10:09:59.428 Info, Node009, Sending (Send) message (Callback ID=0x4e, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x4e, 0xce
2019-12-30 10:09:59.436 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:09:59.436 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:09:59.453 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4e, 0x00, 0x00, 0x02, 0xa7
2019-12-30 10:09:59.453 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4e received (expected 0x4e)
2019-12-30 10:09:59.453 Info, Node009, Request RTT 24 Average Request RTT 28
2019-12-30 10:09:59.453 Detail,   Expected callbackId was received
2019-12-30 10:09:59.453 Detail,   Expected reply was received
2019-12-30 10:09:59.453 Detail,   Message transaction complete
2019-12-30 10:09:59.453 Detail, 
2019-12-30 10:09:59.453 Detail, Node009, Removing current message
2019-12-30 10:09:59.453 Detail, 
2019-12-30 10:09:59.453 Info, Node009, Sending (Send) message (Callback ID=0x4f, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x4f, 0xce
2019-12-30 10:09:59.461 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-30 10:09:59.461 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-30 10:09:59.477 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4f, 0x00, 0x00, 0x02, 0xa6
2019-12-30 10:09:59.477 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4f received (expected 0x4f)
2019-12-30 10:09:59.477 Info, Node009, Request RTT 24 Average Request RTT 26
2019-12-30 10:09:59.477 Detail,   Expected callbackId was received
2019-12-30 10:09:59.524 Detail, Node009,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x03, 0xff, 0x4c
2019-12-30 10:09:59.524 Detail, 
2019-12-30 10:09:59.524 Info, Node009, Response RTT 70 Average Response RTT 57
2019-12-30 10:09:59.524 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_BINARY
2019-12-30 10:09:59.524 Info, Node009, Received SwitchBinary report from node 9: level=On
2019-12-30 10:09:59.524 Detail, Node009, Refreshed Value: old value=true, new value=true, type=bool
2019-12-30 10:09:59.524 Detail, Node009, Changes to this value are not verified
2019-12-30 10:09:59.524 Detail, Node009,   Expected reply and command class was received
2019-12-30 10:09:59.524 Detail, Node009,   Message transaction complete
2019-12-30 10:09:59.524 Detail, 
2019-12-30 10:09:59.524 Detail, Node009, Removing current message
2019-12-30 10:09:59.524 Detail, Node009, Notification: ValueChanged
2019-12-30 10:10:52.200 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - False
2019-12-30 10:10:52.200 Info, Node009, SwitchBinary::Set - Setting node 9 to Off
2019-12-30 10:10:52.200 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x50, 0xd0
2019-12-30 10:10:52.200 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x51, 0xd0
2019-12-30 10:10:52.200 Detail, 
2019-12-30 10:10:52.200 Info, Node009, Sending (Send) message (Callback ID=0x50, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x50, 0xd0
2019-12-30 10:10:53.201 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 10:10:53.201 Detail, Node009, Removing current message
2019-12-30 10:10:53.201 Detail, Node009, Notification: Notification - TimeOut
2019-12-30 10:10:53.202 Detail, 
2019-12-30 10:10:53.202 Info, Node009, Sending (Send) message (Callback ID=0x51, Expected Reply=0x04) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x51, 0xd0
2019-12-30 10:10:54.202 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 10:10:54.202 Detail, Node009, Removing current message
2019-12-30 10:10:54.202 Detail, Node009, Notification: Notification - TimeOut
2019-12-30 10:10:56.018 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - False
2019-12-30 10:10:56.018 Info, Node009, SwitchBinary::Set - Setting node 9 to Off
2019-12-30 10:10:56.018 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x52, 0xd2
2019-12-30 10:10:56.018 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x53, 0xd2
2019-12-30 10:10:56.018 Detail, 
2019-12-30 10:10:56.018 Info, Node009, Sending (Send) message (Callback ID=0x52, Expected Reply=0x13) - MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0x00, 0x25, 0x52, 0xd2
2019-12-30 10:10:56.491 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 2 - True
2019-12-30 10:10:56.491 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2019-12-30 10:10:56.491 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Set (Node=9): 0x01, 0x0e, 0x00, 0x13, 0x09, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x01, 0xff, 0x25, 0x54, 0x2b
2019-12-30 10:10:56.491 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=2): SwitchBinaryCmd_Get (Node=9): 0x01, 0x0d, 0x00, 0x13, 0x09, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x25, 0x02, 0x25, 0x55, 0xd4
2019-12-30 10:10:57.018 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2019-12-30 10:10:57.018 Detail, Node009, Removing current message
2019-12-30 10:10:57.018 Detail, Node009, Notification: Notification - TimeOut

Okay, lots and lots of digging. It appears my USB device is changing ports causing everything to stop working after a hass reboot (if I understand dmesg logs - based on idVendor=0658, which is aeotec)

[432088.854977] usb usb3-port1: disabled by hub (EMI?), re-enabling...
[432088.854982] usb 3-1: USB disconnect, device number 16
[432089.136892] usb 3-1: new full-speed USB device number 17 using xhci_hcd
[432089.285644] usb 3-1: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[432089.285645] usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[432089.286295] cdc_acm 3-1:1.0: ttyACM0: USB ACM device
[432773.737823] udevd[7]: starting version 3.2.8
[432773.746900] udevd[8]: starting eudev-3.2.8
[432980.844564] usb usb3-port1: disabled by hub (EMI?), re-enabling...
[432980.844575] usb 3-1: USB disconnect, device number 17
[432981.119562] usb 3-1: new full-speed USB device number 18 using xhci_hcd
[432981.276212] usb 3-1: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[432981.276214] usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[432981.276884] cdc_acm 3-1:1.0: ttyACM1: USB ACM device
[433457.558328] udevd[8]: starting version 3.2.8
[433457.561302] udevd[9]: starting eudev-3.2.8
[433578.292479] usb usb3-port1: disabled by hub (EMI?), re-enabling...
[433578.292487] usb 3-1: USB disconnect, device number 18
[433578.566670] usb 3-1: new full-speed USB device number 19 using xhci_hcd
[433578.715484] usb 3-1: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[433578.715486] usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[433578.716939] cdc_acm 3-1:1.0: ttyACM0: USB ACM device
[437609.208503] udevd[8]: starting version 3.2.8
[437609.212768] udevd[9]: starting eudev-3.2.8
[437872.908498] usb usb3-port1: disabled by hub (EMI?), re-enabling...
[437872.908504] usb 3-1: USB disconnect, device number 19
[437873.181786] usb 3-1: new full-speed USB device number 20 using xhci_hcd
[437873.330577] usb 3-1: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[437873.330579] usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[437873.331956] cdc_acm 3-1:1.0: ttyACM1: USB ACM device
[459922.856126] udevd[7]: starting version 3.2.8
[459922.880912] udevd[8]: starting eudev-3.2.8
[459992.932259] usb usb3-port1: disabled by hub (EMI?), re-enabling...
[459992.932264] usb 3-1: USB disconnect, device number 20
[459993.204505] usb 3-1: new full-speed USB device number 21 using xhci_hcd
[459993.353328] usb 3-1: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[459993.353330] usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[459993.353986] cdc_acm 3-1:1.0: ttyACM0: USB ACM device
[460588.359334] udevd[7]: starting version 3.2.8
[460588.361917] udevd[8]: starting eudev-3.2.8
[460652.885701] usb usb3-port1: disabled by hub (EMI?), re-enabling...
[460652.885707] usb 3-1: USB disconnect, device number 21
[460653.157936] usb 3-1: new full-speed USB device number 22 using xhci_hcd
[460653.306598] usb 3-1: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[460653.306602] usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[460653.307346] cdc_acm 3-1:1.0: ttyACM1: USB ACM device

It appears to be jumping between ttyACM0 and ttyACM1

Any ideas?

My config is (set-up by the hass -> integrations),

"usb_path": "/dev/serial/by-id/usb-0658_0200-if00"

which matches my

Server:~$ ls /dev/serial/by-*
/dev/serial/by-id:
usb-0658_0200-if00

I’d assumed this would be bypassing the issue of the device jumping from ttyACM0/1

Moved the USB to a new (root) USB which doesn’t seem to have the issue.

Spoke to RobC in Discord and it switching between ttyACM0/1 shouldn’t be causing an issue as I used the /dev/serial/by-id/xxxxxxx to map it.

But it is working and stable for >30 minutes with lots of usage so going to monitor and hopefully that is it.

1 Like

I’ve had some internal hubs do strange stuff, so having the controller off a root USB port is likely a good idea.

1 Like