Dealing with CANs: Retransmission vs. duplicate responses

[AlCalzone]

@hanskroner and one more...

Regarding CAN frames, I find this in the specs:

If a Z-Wave chip expects to receive an ACK frame but receives a Data frame from the host, the Z-Wave chip SHOULD return a CAN frame. A host which receives a CAN frame MUST consider the dataframe lost. The host MUST wait for a period before retransmitting the Data frame.

zwave-js currently does this, but I've found it to be problematic from time to time. I'll need to see if I can scoop up some logs where it happens, but I've seen several occasions where we've tried to SendData, received a CAN, then retransmitted the data frame after a delay, only to be greeted by two replies from the controller and/or node. Is there anything else that needs to be done?

[hanskroner]

I think it's best to start with a bit of background info:

The SerialAPI protocol that Z-Wave uses to communicate with host controllers borrows 4 control characters from the ASCII control codes:

0x01 - SOH - Start of Heading (SerialAPI calls this SOF - Start of Frame)
0x06 - ACK - Acknowledge
0x15 - NAK - Negative Acknowledge
0x18 - CAN - Cancel

In the context of control codes, CAN is used to "indicate that the data preceding it are in error or are to be disregarded."

Over the past almost two decades, the state machine that drives the Z-Wave protocol's serial communication has been put through a lot, by a lot of different clients. Like any piece of software, it had bugs and design oversights that resulted in deadlocks or unexpected transmissions - I think it's fair to say the vast majority of those have been ironed out by now. Nobody's going as far as saying it's perfect, but these days when you receive a CAN frame the problem is much more likely to be on the host's side. In other words, you don't so much "deal with CAN frames" you rather "improve your serial communication so you don't cause them."

You're seeing CAN frames because you're asking something of the Z-Wave protocol when it's not in a state where it can handle your request. To figure out what's going on, we'll definitely need some logs of the serial communication where this is happening. It's helpful if the logs go back quite a bit, not just showing the moment where the CAN frame is being received.

[AlCalzone]

@hanskroner Not exactly what I was describing above, but I found a couple of CANs in the wild:

18:07:44.322 CNTRLR   [Node 037] BinarySwitchCC: doing a partial interview...
18:07:44.323 CNTRLR » [Node 037] querying Binary Switch state...
18:07:44.683 SERIAL » 0x0109001319027204250fa2                                            (11 bytes)
18:07:44.684 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      15
                      └─[ManufacturerSpecificCCGet]
18:07:44.687 SERIAL « [ACK]                                                                   (0x06)
18:07:44.690 SERIAL « 0x0104011300e9                                                       (6 bytes)
18:07:44.690 SERIAL » [ACK]                                                                   (0x06)
18:07:44.692 DRIVER « [RES] [SendData]
                        was sent: false
18:07:44.694 CNTRLR   The controller response indicated failure after 1/3 attempts. Scheduling next 
                      try in 100 ms.
18:07:44.796 SERIAL » 0x0109001319027204250fa2                                            (11 bytes)
18:07:44.798 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      15
                      └─[ManufacturerSpecificCCGet]
18:07:45.801 CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                      n 1100 ms.
18:07:46.903 SERIAL » 0x0109001319027204250fa2                                            (11 bytes)
18:07:46.904 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      15
                      └─[ManufacturerSpecificCCGet]
18:07:47.908 CNTRLR   [Node 025] did not respond after 2/3 attempts. Scheduling next try in 500 ms.
18:07:48.415 SERIAL » 0x0109001319027204250fa2                                            (11 bytes)
18:07:48.416 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      15
                      └─[ManufacturerSpecificCCGet]
18:07:49.420 CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                      n 100 ms.
18:07:49.521 SERIAL » 0x0109001319027204250fa2                                            (11 bytes)
18:07:49.522 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      15
                      └─[ManufacturerSpecificCCGet]
18:07:50.525 CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                      n 1100 ms.
18:07:51.627 SERIAL » 0x0109001319027204250fa2                                            (11 bytes)
18:07:51.628 DRIVER » [Node 025] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      15
                      └─[ManufacturerSpecificCCGet]
18:07:52.639 SERIAL » 0x010d00132506600d000225022510bf                                    (15 bytes)
18:07:52.641 DRIVER » [Node 037] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      16
                      └─[MultiChannelCCCommandEncapsulation]
                        │ source:      0
                        │ destination: 2
                        └─[BinarySwitchCCGet]
18:07:52.642 CNTRLR   [Node 025] Error during node interview: Timeout while waiting for an ACK from 
                      the controller
18:07:53.644 CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                      n 100 ms.
18:07:53.747 SERIAL » 0x010d00132506600d000225022510bf                                    (15 bytes)
18:07:53.748 DRIVER » [Node 037] [REQ] [SendData]
                      │ transmit options: 0x25
                      │ callback id:      16
                      └─[MultiChannelCCCommandEncapsulation]
                        │ source:      0
                        │ destination: 2
                        └─[BinarySwitchCCGet]
18:07:54.222 SERIAL « [ACK]                                                                   (0x06)
18:07:54.225 SERIAL « 0x0104011300e9                                                       (6 bytes)
18:07:54.226 SERIAL » [ACK]                                                                   (0x06)
18:07:54.227 DRIVER « [RES] [SendData]
                        was sent: false
18:07:54.229 CNTRLR   The controller response indicated failure after 2/3 attempts. Scheduling next 
                      try in 1100 ms.
18:07:54.232 SERIAL « [CAN]                                                                   (0x18)
18:07:54.233 SERIAL « [CAN]                                                                   (0x18)
18:07:54.234 SERIAL « [CAN]                                                                   (0x18)
18:07:54.235 SERIAL « [CAN]                                                                   (0x18)
18:07:54.236 SERIAL « [CAN]                                                                   (0x18)
18:07:54.238 SERIAL « [CAN]                                                                   (0x18)

The communication worked before, but for some reason the controller did not respond to anything for about 10 seconds here. The initial commands are retried because the response timeout has elapsed.

[Xrlls]

It is interesting what the Z-Wave module is doing here, generally you should not, or at least only extremely rarely see Zw_senddata return false, as long as you are not attempting to send multiple outgoing frames at the same time. The module could also be stuck in another process, such as add_node, that has not been terminated with enough add_node_stop's :) It is even stranger that you are not seeing any acks to the serial API messages following the first attempt.

On a siden ote, you may consider rewriting you project to use ZW_SendData_Bridge, which while requiring a bridge library is compatible with the 700 series, which only features a bridge library :)

[AlCalzone]

On a siden ote, you may consider rewriting you project to use ZW_SendData_Bridge, which while requiring a bridge library is compatible with the 700 series, which only features a bridge library :)

I've added support for the Bridge Application Command Handler, because some people with a 700-series stick needed that. But it seems they are working with the non-bridge SendData API.

What's the benefit of using ZW_SendData_Bridge and are there specifications available for the 700-series? I only have ones for the 500.

[Xrlls]

There is no particular benefit of the zw_senddatabridge unless you for some reason need to transmit and receive on multiple node IDs to simulate multiple Z-Wave nodes with one physical radio. The main benefit for most applications to use this API is for compatibility reasons with the bridge library.

The 700 series serial API documentation is in progress, and should hopefully be released soon. I actually did not think that zw_senddata was implemented on the 700 series, but I just tried, and I can see that it is :)

[hanskroner]

As I mentioned originally, it'll be helpful to see the serial traces going back quite a bit before the CAN frames show up. Like @Silabs-Crilles mentions, there could be actions ongoing that prevent the Z-Wave module from executing the action you're requesting.

[AlCalzone]

I really need to remember where I copied that log from. Will update here when I find it.