zStack Parsing Error & Manufacturer Custom Command reported multiple times

[schrluka]

Hello

We develop a zigbee in-wall light switch called zigfred and have a custom converter that implements decoding of a manufacturer specific command. We use it to publish an event when the user presses a button on our switch. This works flawlessly with conbee 2 and conbee 3 sticks used as coordinators. However, there are two (likely related) issues with zStack based dongles such as the sonoff dongle p.

1. A bounds error occurs in z-Stack unpi:
While is this no issue for our us, it is annoying because of the message in th UI and it might point to some underlying issue. Here is the execption, a complete debug log is attached.

[2024-07-01 17:05:24] error:    zh:zstack:znp: Error while parsing to ZpiObject 'RangeError: The value of "offset" is out of range. It must be >= 0 and <= 6. Received 7
    at boundsError (node:internal/buffer:88:9)
    at Buffer.readUInt16LE (node:internal/buffer:245:5)
    at BuffaloZnp.readUInt16 (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/buffalo/buffalo.ts:45:35)
    at BuffaloZnp.readListUInt16 (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/buffalo/buffalo.ts:233:29)
    at BuffaloZnp.read (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/buffaloZnp.ts:265:25)
    at Function.readParameters (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/zpiObject.ts:107:46)
    at Function.fromUnpiFrame (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/zpiObject.ts:73:30)
    at Znp.onUnpiParsed (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:93:38)
    at Parser.emit (node:events:519:28)
    at Parser.parseNext (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/z-stack/unpi/parser.ts:45:26)'

2. The resulting action is published multiple times in MQTT.
This is the real issue for us, as our customers subscribe to the topic to perform actions such as controlling non-zigbee lights.
It appears to me that the frame is decoded multiple times by unpi parser, but I lack unterstanding of it.
A capture with a 802.15.4 sniffer shows that the frame was transmitted, but not ACKed by the coordinator and the retransmitted and ACKed. So the total number of transmissions was two, but the zigbee messages was received (and the topic published) 12 times.
Here is an excerpt of the log:

2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: <-- [254,27,68,129,0,0,66,252,70,215,5,13,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,167,254,27,68,129,0,0,66,252,70,215,5,12,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,166,254,27,68,129,0,0,66,252,70,215,5,110,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,196,254,27,68,129,0,0,66,252,70,215,5,11,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,161,
254,27,68,129,0,0,66,252,70,215,5,10,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,160,254,27,68,129,0,0,66,252,70,215,5,8,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,162,254,27,68,129,0,0,66,252,70,215,5,6,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,172,254,27,68,129,0,0,66,252,70,215,5,5,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,175,254,27,68,129,0,0,66,252,70,215,5,4,0,116,0,70,166,69,0,0,7,17,2
1,2,3,1,0,0,70,215,29,174,254,27,68,129,0,0,66,252,70,215,5,3,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,169,254,27,68,129,0,0,66,252,70,215,5,2,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,168,254,27,68,129,0,0,66,252,70,215,5,1,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,171,254,8,69,194,70,215,21,2,3,1,0,0,11]
[2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: --- parseNext [254,27,68,129,0,0,66,252,70,215,5,13,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,167,254,27,68,129,0,0,66,252,70,215,5,12,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,166,254,27,68,129,0,0,66,252,70,215,5,110,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,196,254,27,68,129,0,0,66,252,70,215,5,11,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,2
15,29,161,254,27,68,129,0,0,66,252,70,215,5,10,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,160,254,27,68,129,0,0,66,252,70,215,5,8,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,162,254,27,68,129,0,0,66,252,70,215,5,6,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,172,254,27,68,129,0,0,66,252,70,215,5,5,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,175,254,27,68,129,0,0,66,252,70,215,5,4,0,116,0,70,166,69,
0,0,7,17,21,2,3,1,0,0,70,215,29,174,254,27,68,129,0,0,66,252,70,215,5,3,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,169,254,27,68,129,0,0,66,252,70,215,5,2,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,168,254,27,68,129,0,0,66,252,70,215,5,1,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,171,254,8,69,194,70,215,21,2,3,1,0,0,11]
[2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: --> parsed 27 - 2 - 4 - 129 - [0,0,66,252,70,215,5,13,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29] - 167
[2024-07-01 17:05:24] debug:    zh:zstack:znp: AREQ: <-- AF - incomingMsg - {"groupid":0,"clusterid":64578,"srcaddr":55110,"srcendpoint":5,"dstendpoint":13,"wasbroadcast":0,"linkquality":116,"securityuse":0,"timestamp":4564550,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[17,21,2,3,1,0,0]}}
[2024-07-01 17:05:24] debug:    zh:controller: Received payload: clusterID=64578, address=55110, groupID=0, endpoint=5, destinationEndpoint=13, wasBroadcast=false, linkQuality=116, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":21,"commandIdentifier":2},"payload":{"button":3,"type"
:1,"duration":0},"command":{"ID":2,"parameters":[{"name":"button","type":32},{"name":"type","type":32},{"name":"duration","type":33}],"name":"siglisZigfredButtonEvent"}}
[2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: --- parseNext [254,27,68,129,0,0,66,252,70,215,5,12,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,166,254,27,68,129,0,0,66,252,70,215,5,110,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,196,254,27,68,129,0,0,66,252,70,215,5,11,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,161,254,27,68,129,0,0,66,252,70,215,5,10,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,2
15,29,160,254,27,68,129,0,0,66,252,70,215,5,8,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,162,254,27,68,129,0,0,66,252,70,215,5,6,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,172,254,27,68,129,0,0,66,252,70,215,5,5,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,175,254,27,68,129,0,0,66,252,70,215,5,4,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,174,254,27,68,129,0,0,66,252,70,215,5,3,0,116,0,70,166,69,0
,0,7,17,21,2,3,1,0,0,70,215,29,169,254,27,68,129,0,0,66,252,70,215,5,2,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,168,254,27,68,129,0,0,66,252,70,215,5,1,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,171,254,8,69,194,70,215,21,2,3,1,0,0,11]
[2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: --> parsed 27 - 2 - 4 - 129 - [0,0,66,252,70,215,5,12,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29] - 166
[2024-07-01 17:05:24] debug:    zh:zstack:znp: AREQ: <-- AF - incomingMsg - {"groupid":0,"clusterid":64578,"srcaddr":55110,"srcendpoint":5,"dstendpoint":12,"wasbroadcast":0,"linkquality":116,"securityuse":0,"timestamp":4564550,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[17,21,2,3,1,0,0]}}
[2024-07-01 17:05:24] debug:    zh:controller: Received payload: clusterID=64578, address=55110, groupID=0, endpoint=5, destinationEndpoint=12, wasBroadcast=false, linkQuality=116, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":21,"commandIdentifier":2},"payload":{"button":3,"type"
:1,"duration":0},"command":{"ID":2,"parameters":[{"name":"button","type":32},{"name":"type","type":32},{"name":"duration","type":33}],"name":"siglisZigfredButtonEvent"}}
[2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: --- parseNext [254,27,68,129,0,0,66,252,70,215,5,110,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,196,254,27,68,129,0,0,66,252,70,215,5,11,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,161,254,27,68,129,0,0,66,252,70,215,5,10,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,160,254,27,68,129,0,0,66,252,70,215,5,8,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,21
5,29,162,254,27,68,129,0,0,66,252,70,215,5,6,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,172,254,27,68,129,0,0,66,252,70,215,5,5,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,175,254,27,68,129,0,0,66,252,70,215,5,4,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,174,254,27,68,129,0,0,66,252,70,215,5,3,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,169,254,27,68,129,0,0,66,252,70,215,5,2,0,116,0,70,166,69,0,
0,7,17,21,2,3,1,0,0,70,215,29,168,254,27,68,129,0,0,66,252,70,215,5,1,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,171,254,8,69,194,70,215,21,2,3,1,0,0,11]
[2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: --> parsed 27 - 2 - 4 - 129 - [0,0,66,252,70,215,5,110,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29] - 196
[2024-07-01 17:05:24] debug:    zh:zstack:znp: AREQ: <-- AF - incomingMsg - {"groupid":0,"clusterid":64578,"srcaddr":55110,"srcendpoint":5,"dstendpoint":110,"wasbroadcast":0,"linkquality":116,"securityuse":0,"timestamp":4564550,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[17,21,2,3,1,0,0]}}
[2024-07-01 17:05:24] debug:    zh:controller: Received payload: clusterID=64578, address=55110, groupID=0, endpoint=5, destinationEndpoint=110, wasBroadcast=false, linkQuality=116, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":21,"commandIdentifier":2},"payload":{"button":3,"type
":1,"duration":0},"command":{"ID":2,"parameters":[{"name":"button","type":32},{"name":"type","type":32},{"name":"duration","type":33}],"name":"siglisZigfredButtonEvent"}}
[2024-07-01 17:05:24] debug:    zh:zstack:unpi:parser: --- parseNext [254,27,68,129,0,0,66,252,70,215,5,11,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,161,254,27,68,129,0,0,66,252,70,215,5,10,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,160,254,27,68,129,0,0,66,252,70,215,5,8,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,162,254,27,68,129,0,0,66,252,70,215,5,6,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,
29,172,254,27,68,129,0,0,66,252,70,215,5,5,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,175,254,27,68,129,0,0,66,252,70,215,5,4,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,174,254,27,68,129,0,0,66,252,70,215,5,3,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,169,254,27,68,129,0,0,66,252,70,215,5,2,0,116,0,70,166,69,0,0,7,17,21,2,3,1,0,0,70,215,29,168,254,27,68,129,0,0,66,252,70,215,5,1,0,116,0,70,166,69,0,0,
7,17,21,2,3,1,0,0,70,215,29,171,254,8,69,194,70,215,21,2,3,1,0,0,11]

One question: our devices simply send this command to 0x000 (i.e. the coordinator) and endpoint 0xFF, which is 'any endpoint'. Could this be an issue for the coordinator firmware?

A possible workaround for this is to modify our custom converter, such that it filters for repeating TSN. A patch for zigbee-herdsman-converters-v19.47.1 is attached as well. If the issue is difficult to debug or fix, I would appreciate if that fix can be merged into herdsman/converters. (If you like I can perpare a merge request for this of course.)

Let me know if there is anything else I can help you with to debug it.

Thank's in advance for looking into this.

Best regards,
Lukas from zigfred / siglis

heardsman bug report.zip

[schrluka]

Hello

As an addon: if our device sends the same command to endpoint 1 on the coordinator both issues are solved. While this works for now, it is not nice because the EP is hardcoded in our product now. We can make it configurable, but that is not so nice for our customers because it is extra effort for them...

BR,
Lukas