Interferencing the communication with Z-Wave

[CiTroNaK]

When your component is placed in custom_components (even without configured) it interference with the communication with the Z-Wave module (/dev/ttyAMA0).

I did a clean install with only two integrations (yours and Z-Wave) to test it.

I am using rPi 3 with Raspberry Pi OS Lite (32bit) and installed HA using supervised-installer. For Z-Wave, I am using razberry.

Without your component (working Z-Wave):

2020-10-23 12:32:10.793 Always, OpenZwave Version 1.4.3469 Starting Up
2020-10-23 12:32:17.527 Info, Setting Up Provided Network Key for Secure Communications
2020-10-23 12:32:17.527 Info, mgr,     Added driver for controller /dev/ttyAMA0
2020-10-23 12:32:17.527 Info,   Opening controller /dev/ttyAMA0
2020-10-23 12:32:17.528 Info, Trying to open serial port /dev/ttyAMA0 (attempt 1)
2020-10-23 12:32:17.528 Info, Serial port /dev/ttyAMA0 opened (attempt 1)
2020-10-23 12:32:17.528 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2020-10-23 12:32:17.528 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2020-10-23 12:32:17.529 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2020-10-23 12:32:17.529 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2020-10-23 12:32:17.529 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2020-10-23 12:32:17.529 Detail,
2020-10-23 12:32:17.529 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2020-10-23 12:32:17.533 Detail, Unsolicited message received while waiting for ACK.
2020-10-23 12:32:17.538 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x36, 0x31, 0x00, 0x01, 0x95
2020-10-23 12:32:17.538 Detail,
2020-10-23 12:32:17.538 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2020-10-23 12:32:17.538 Info, contrlr,     Static Controller library, version Z-Wave 4.61
2020-10-23 12:32:17.538 Detail, Node045,   Expected reply was received
2020-10-23 12:32:17.538 Detail, Node045,   Message transaction complete
2020-10-23 12:32:17.538 Detail,
2020-10-23 12:32:17.538 Detail, contrlr, Removing current message
2020-10-23 12:32:17.538 Detail,
2020-10-23 12:32:17.538 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2020-10-23 12:32:18.535 Detail, Unsolicited message received while waiting for ACK.
2020-10-23 12:32:18.535 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xe0, 0xbe, 0xe8, 0x96, 0x01, 0xf7
2020-10-23 12:32:18.535 Detail,
2020-10-23 12:32:18.535 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xe0bee896.  Our node ID = 1
2020-10-23 12:32:18.535 Detail, Node190,   Expected reply was received
2020-10-23 12:32:18.535 Detail, Node190,   Message transaction complete
2020-10-23 12:32:18.535 Detail,

When your component is placed in custom_components:

2020-10-23 12:29:24.989 Always, OpenZwave Version 1.4.3469 Starting Up
2020-10-23 12:29:34.099 Info, Setting Up Provided Network Key for Secure Communications
2020-10-23 12:29:34.100 Info, mgr,     Added driver for controller /dev/ttyAMA0
2020-10-23 12:29:34.100 Info,   Opening controller /dev/ttyAMA0
2020-10-23 12:29:34.101 Info, Trying to open serial port /dev/ttyAMA0 (attempt 1)
2020-10-23 12:29:34.101 Info, Serial port /dev/ttyAMA0 opened (attempt 1)
2020-10-23 12:29:34.101 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2020-10-23 12:29:34.102 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2020-10-23 12:29:34.102 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2020-10-23 12:29:34.102 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2020-10-23 12:29:34.102 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2020-10-23 12:29:34.102 Detail, 
2020-10-23 12:29:34.102 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2020-10-23 12:29:34.104 Detail, Unsolicited message received while waiting for ACK.
2020-10-23 12:29:34.604 Warning, WARNING: 500ms passed without reading the rest of the frame...aborting frame read
2020-10-23 12:29:34.605 Detail, Unsolicited message received while waiting for ACK.
2020-10-23 12:29:35.105 Warning, WARNING: 500ms passed without reading the rest of the frame...aborting frame read
2020-10-23 12:29:35.106 Warning, WARNING: Out of frame flow! (0x5a).  Sending NAK.
2020-10-23 12:29:36.114 Warning, WARNING: Out of frame flow! (0x7b).  Sending NAK.
2020-10-23 12:29:37.114 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-10-23 12:29:37.114 Detail, contrlr, Removing current message
2020-10-23 12:29:37.114 Detail, contrlr, Notification: Notification - TimeOut
2020-10-23 12:29:37.126 Detail, 
2020-10-23 12:29:37.126 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2020-10-23 12:29:38.128 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-10-23 12:29:38.128 Detail, contrlr, Removing current message
2020-10-23 12:29:38.128 Detail, contrlr, Notification: Notification - TimeOut
2020-10-23 12:29:38.138 Detail, 
2020-10-23 12:29:38.138 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2020-10-23 12:29:39.138 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-10-23 12:29:39.138 Detail, contrlr, Removing current message
2020-10-23 12:29:39.138 Detail, contrlr, Notification: Notification - TimeOut
2020-10-23 12:29:39.139 Detail, 
2020-10-23 12:29:39.139 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2020-10-23 12:29:40.139 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-10-23 12:29:40.139 Detail, contrlr, Removing current message
2020-10-23 12:29:40.139 Detail, contrlr, Notification: Notification - TimeOut
2020-10-23 12:29:40.145 Detail, 
2020-10-23 12:29:40.145 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2020-10-23 12:29:41.145 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-10-23 12:29:41.145 Detail, contrlr, Removing current message
2020-10-23 12:29:41.145 Detail, contrlr, Notification: Notification - TimeOut

Could you please look at it?

Please, let me know if you need anything from me.

Thank you very much.

[kukulich]

I'm sorry, I don't understand your logs - it's beyond my knowledge.

However, I don't think that unconfigured integration can cause this. It does not connect anywhere without installation.

[CiTroNaK]

Me neither, but it shows that Z-Wave commands were timeout. I did everything to narrow down the possible cause and end up with this. If you are sure it could not cause it, I am screwed 😅

[kukulich]

I’m pretty sure that the uninstalled integration cannot cause this.

The integration has to be configured first and the default value is “/dev/hidraw0”.

[CiTroNaK]

It is weird, but after I tested a lot of things (different rPi, systems and so), it looks like that the Z-Wave module is broken... Thank you for your time.