search

shimmeringbee / zstack

Implementation of a ZNP and support code designed to interface with Texas Instruments Z-Stack, written in Go.
https://shimmeringbee.io/
Apache License 2.0
27 stars 8 forks source link

Z-Stack appears to crash on CC2652R #22

Closed pwood closed 2 months ago

pwood commented 3 years ago

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 commented 3 years ago

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_MAXDATABUFS* 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 commented 3 years ago

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 commented 3 years ago

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

pwood commented 2 years ago

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

Will test.

pwood commented 2 months ago

I don't know where I am with this anymore, closing for now.