zstack icon indicating copy to clipboard operation
zstack copied to clipboard

Published 20 hours ago • verified publisher icon shimmeringbee

Z-Stack appears to crash on CC2652R

Open pwood opened this issue 2 years ago • 4 comments

On a large network after an short to medium amount of time the USB stick appears to crash. With two sticks running alongside each other, the network with 50 devices will crash, the stick with 2 devices remains stable.

Looking at zigbee2mqtt's zigbee-herdsman the implementation for znp uses a queue with concurrency limits. Searching their previous issues suggests the crashes can happen due to very busy interaction with the stick.

Our implementation needs to look into a technique to limit concurrency, we could either queue go routines in a queue with a pool of go routines (ala zigbee-herdsman), or some kind of syncronisation mechanism similar to a concurrency limited rwmutex.

pwood avatar Aug 07 '21 11:08 pwood

So the above commit does seem to have reduced the frequency, but it has reoccurred and we have the following additional information thanks to debugging.

2021/09/06 11:30:38 [ERROR] "Failed to request LQI table, adapter returned error code." {"IEEEAddress":"00124b00194a2438","NetworkAddress":24514,"Status":17,"gateway":"cc2652r-1"}

Status 17 is ZBufferFull, I found this online:

ZBufferFull is dependent on the availability of NWK_MAX_DATABUFS_* but NWK_INDIRECT_MSG_MAX_PER also has an effect on NWK_INDIRECT_MSG_MAX_ALL. DNWK_INDIRECT_MSG_TIMEOUT from f8wConfig.cfg is the amount of time a parent will hold a message for its sleepy child.

Unpi traffic at the time.

652r-1"}
2021/09/06 10:30:35 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"wl8D"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":5,"CommandID":49,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":5,"CommandID":177,"Payload":"IVoADAADPE208+YnpiZiBWAhAEsSAAAACAIAADxNtPPmJ6Ym58MGBACNFQAEGxICAhI8TbTz5iemJkb2/AQAjRUADDQSAgJA"},"gateway":"cc2
652r-1"}
2021/09/06 10:30:35 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"IVoD"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":5,"CommandID":49,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":5,"CommandID":177,"Payload":"wl8ABgMDPE208+YnpiYj2EoZAEsSAOF2OQL/ADxNtPPmJ6YmRH7ZFABLEgAhWjkC/wE8TbTz5iemJsDwSRkASxIADjM5Av8B"},"gateway":"cc2
652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":5,"CommandID":177,"Payload":"DjMABwADPE208+YnpiYj2EoZAEsSAOF2CQIBATxNtPPmJ6YmDmMGBACNFQB/HxICAzw8TbTz5iemJjT2/AQAjRUAnYoSAgM8"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"DjMD"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":5,"CommandID":49,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":5,"CommandID":177,"Payload":"IVoADAMDPE208+YnpiZAn0QEAI0VAIclEgICSzxNtPPmJ6Ym4GIGBACNFQC3vRICAls8TbTz5iemJmPwqw8Abw0AM/ASAgKq"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEG"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"IVoG"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":5,"CommandID":49,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":5,"CommandID":177,"Payload":"DjMABwMDPE208+YnpiaSn0QEAI0VAOpuEgIDSjxNtPPmJ6YmRH7ZFABLEgAhWjkC/wE8TbTz5iemJmIFYCEASxIAAAA4Av8B"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"DjMG"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":5,"CommandID":49,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":5,"CommandID":177,"Payload":"IVoADAYDPE208+YnpiYiM7QEAI0VAN8uEgICNDxNtPPmJ6YmUZVLBACNFQB5kxICAhM8TbTz5iemJnh3RAUAjRUAti4SAgIP"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"IVoJ"},"gateway":"cc2652r-1"}
2021/09/06 10:30:35 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":5,"CommandID":49,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"/R4BAQEACAAgBQD2ACAA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"6QEI"},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"v+YBAQEAEwAgBQCsACAA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"KfMBAQEAAgAgBQDlACAA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"lMYBAQEABQAgBQAIACAA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AER"},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEJ"},"gateway":"cc2652r-1"}
2021/09/06 10:30:37 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEF"},"gateway":"cc2652r-1"}
2021/09/06 10:30:38 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEP"},"gateway":"cc2652r-1"}
2021/09/06 10:30:38 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEK"},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"/R4BAQEAEgAgBQD3ACAA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"6QES"},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"v+YBAQEAAQAgBQCtACAA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"KfMBAQEABwAgBQDmACAA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2t4BAQEADgAgBQDmACEA"},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 10:30:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEQ"},"gateway":"cc2652r-1"}

pwood avatar Sep 07 '21 16:09 pwood

Actually scrub the above, that's not the actual failure. It keeps working on afterwards. The first failure is actually.

2021/09/06 12:27:03 [ERROR] "Failed to request LQI table." {"IEEEAddress":"00124b0021600562","NetworkAddress":0,"err":"context cancelled","gateway":"cc2652r-1"}

Unpi at time:

2021/09/06 12:26:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:40 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"AAEO"},"gateway":"cc2652r-1"}
2021/09/06 12:26:41 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2r4BAQEAAwAgBQCrACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:41 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:41 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"lMYBAQEAEQAgBQDPACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:41 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:41 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEI"},"gateway":"cc2652r-1"}
2021/09/06 12:26:42 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"v+YBAQEABAAgBQB7ACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:42 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:42 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"8AEC"},"gateway":"cc2652r-1"}
2021/09/06 12:26:43 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"3y4BAQEACwAgBQB8ACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:43 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:43 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":128,"Payload":"AAEL"},"gateway":"cc2652r-1"}
2021/09/06 12:26:43 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":129,"Payload":"AAABAN8uAQEADwD7RlQAAAcI3QohACDIwl8b"},"gateway":"cc2652r-1"}
2021/09/06 12:26:43 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":129,"Payload":"AAABAN8uAQEADwCbUlQAAAgIeAEhAAAgyMJfGw=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:43 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":129,"Payload":"AAABAN8uAQEADwB4gFQAAAgIeQEhAAAgyMJfGw=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:44 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":2,"Subsystem":4,"CommandID":129,"Payload":"AAABAN8uAQEADwDqtFQAAAgIegEhAAAgyMJfGg=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:44 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2r4BAQEABgAgBQCsACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:44 [TRACE] "Inbound UNPI Frame" {"frame":{"MessageType":3,"Subsystem":4,"CommandID":1,"Payload":"AA=="},"gateway":"cc2652r-1"}
2021/09/06 12:26:44 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"lMYBAQEACQAgBQDQACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:47 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"v+YBAQEADwAgBQB8ACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:48 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2t4BAQEACgAgBQC0ACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:49 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2r4BAQEADQAgBQCtACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:50 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2r4BAQEACAAgBQCuACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:53 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"lMYBAQEAEAAgBQDRACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:54 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"nYoBAQEAAAAgBQDnACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:54 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2t4BAQEADAAgBQC1ACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:54 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2r4BAQEAEwAgBQCvACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:56 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"lMYBAQEAAgAgBQDSACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:56 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"nYoBAQEABQAgBQDoACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:57 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2t4BAQEAEgAgBQC2ACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:57 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2r4BAQEAAQAgBQCwACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:59 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"lMYBAQEABwAgBQDTACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:26:59 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"nYoBAQEADgAgBQDpACEA"},"gateway":"cc2652r-1"}
2021/09/06 12:27:00 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":4,"CommandID":1,"Payload":"2t4BAQEAAwAgBQC3ACAA"},"gateway":"cc2652r-1"}
2021/09/06 12:27:00 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"AAAA"},"gateway":"cc2652r-1"}
2021/09/06 12:27:03 [TRACE] "Outbound UNPI Frame" {"frame":{"MessageType":1,"Subsystem":5,"CommandID":49,"Payload":"85kA"},"gateway":"cc2652r-1"}

pwood avatar Sep 07 '21 16:09 pwood

Opening up the USB tty shows no data at all coming from the USB stick.

pwood avatar Sep 07 '21 16:09 pwood

It's probably this: https://www.reddit.com/r/homeassistant/comments/l9uhvm/psa_zigbee_network_lockup_bug_affecting/

Will test.

pwood avatar Nov 24 '21 19:11 pwood