duplicate data indication 0x8002

[G1K]

In raw mode, messages are often duplicated with one sqn coming in 2 messages each. Judging by my tests, the callback for the endpoint in the sdk is called several times. I'm not sure about the correctness, but that's how it seems to work and doesn't cause duplication

G1K@be7d6a6

[G1K]

Firmware for testing can be taken here https://github.com/G1K/ZiGate/actions/runs/479754512

[pipiche38]

This is correct, and up to the application layer to deduplicate . This is at least what we do on hybrid and normal mode

[G1K]

And what is the point of sending two identical messages via UART, is it possible to deduplicate at the firmware level?

[pipiche38]

please feel free to propose a PR doing the deduplication.
We are just trying to limit the amount of code in the firmware due the the RAM limitation

[G1K]

My knowledge of C is only enough to remove the re-call. Please tell me what this can affect and in what cases?

[pipiche38]

I don't understand what you mean, just do the deduplication at the application level, this is also why the SQN is provided.

I leave @fairecasoimeme to comment

[KiwiHC16]

I was looking at this topic and found this issue so will add my info here:

Zigate, sometime, duplicates messages on USB interfaces.

One message on air interface (no repetition):

One for SQN 137, SQN138, SQN139

Details for SQN138:

Then on USB port of zigate (3.1D in Hybrid mode) for SQN 138 (0x8A):

[2021-01-20 10:43:08][debug] Reçu: "800200172A0001040B04010102ADDE02000018 8A 0105050021EB009F"
[2021-01-20 10:43:08][debug] Reçu: "800200172A0001040B04010102ADDE02000018 8A 0105050021EB009F"

we have duplication.

I see it only with message 8002 (Hybrid I guess) but not all the time.

For example a unique one:

[2021-01-20 10:43:05][debug] Reçu: "80020016E900010400080101023EFE02000018 88 0100000020FEFF"

which is on air interface:

The difference I see is that no duplication for cluster 0008(Level) which is known by Zigate and the other one cluster 0B04 is unknown by zigate.

I can reproduce easly for tracing needs.

[pipiche38]

You have duplication due to the Hybrid mode, no ?
Hybrid mode has been created for debuging purposes and will send the 0x8002 message as well as the message fully handled by the Zigbee Stack . Maybe @Badz or @fairecasoimeme can comment

[KiwiHC16]

@fairecasoimeme told me that hybrid mode can be used for messages unknown by zigate.
Anyway it doesn't explain the behavior above.

[fairecasoimeme]

The hybrid mode permit to catch messages which is not known by ZiGate and manage the "classic" packet too
with KiwiHC16 traces, we can see a duplication. There is perhaps, in theFirmware, a double handling.
For the moment, please refer to SQN to ignore a duplicate packet.
Fred

[G1K]

I wrote about the raw mode, not the hybrid mode. the duplication that I found is in this comment here #346 (comment)

[fairecasoimeme]

OK, we will see. thx

[fairecasoimeme]

I'm just investigate and this is not really a duplicate packet, It's just read attribute type which generate 2 callback handling.
But there is a type (E_ZCL_CBET_REPORT_ATTRIBUTES) which don't give a message on UART. I will create a PR to filter this type.

[fairecasoimeme]

I add E_ZCL_CBET_READ_ATTRIBUTES_RESPONSE in filter for the same reason. Thanks to @KiwiHC16 sniff

[G1K]

I tried the last solution, but it doesn't quite work. some messages are duplicated. For example, from the square button aqara single click is duplicated, and double is not

2021-01-25T09:57:09.741Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:09.743Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 18' }
2021-01-25T09:57:09.746Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:09.747Z { logLevel: 'INFO ', log: 'EP EVT: Invalid event type' }
2021-01-25T09:57:12.916Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:12.919Z { logLevel: 'INFO ', log: 'Got bdb event 1' }
2021-01-25T09:57:12.921Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:12.923Z { logLevel: 'INFO ', log: 'ZCL_Task got event 1' }
2021-01-25T09:57:12.936Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:12.938Z { logLevel: 'INFO ', log: 'DATA: SEP=1 DEP=1 Profile=0104 Cluster=0006' }
2021-01-25T09:57:12.941Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:12.943Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 17' }
2021-01-25T09:57:12.948Z { msgCodeBytes: <Buffer 80 02>, msgLengthBytes: <Buffer 00 19>, checksumBytes: <Buffer aa>, msgPayloadBytes: <Buffer 00 01 04 00 06 01 01 02 53 c3 02 00 00 18 11 0a 00 00 10 00 00 00 10 01>, rssiBytes: <Buffer a0>, msgLengthOffset: -1 }
2021-01-25T09:57:12.949Z --> parsed frame �[1;34m>>>> DataIndication 0x8002 <<<<�[0m 
2021-01-25T09:57:12.952Z { status: 0, profileID: 260, clusterID: 6, sourceEndpoint: 1, destinationEndpoint: 1, sourceAddressMode: 2, sourceAddress: 21443, destinationAddressMode: 2, destinationAddress: 0, payload: <Buffer 18 11 0a 00 00 10 00 00 00 10 01> }
2021-01-25T09:57:12.959Z  Received 'zcl' data '{"address":21443,"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":17,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":16,"attrData":0},{"attrId":0,"dataType":16,"attrData":1}]},"endpoint":1,"linkquality":160,"groupID":null}'
2021-01-25T09:57:12.968Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:12.970Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 17' }
2021-01-25T09:57:12.975Z { msgCodeBytes: <Buffer 80 02>, msgLengthBytes: <Buffer 00 19>, checksumBytes: <Buffer aa>, msgPayloadBytes: <Buffer 00 01 04 00 06 01 01 02 53 c3 02 00 00 18 11 0a 00 00 10 00 00 00 10 01>, rssiBytes: <Buffer a0>, msgLengthOffset: -1 }
2021-01-25T09:57:12.976Z --> parsed frame �[1;34m>>>> DataIndication 0x8002 <<<<�[0m 
2021-01-25T09:57:12.979Z { status: 0, profileID: 260, clusterID: 6, sourceEndpoint: 1, destinationEndpoint: 1, sourceAddressMode: 2, sourceAddress: 21443, destinationAddressMode: 2, destinationAddress: 0, payload: <Buffer 18 11 0a 00 00 10 00 00 00 10 01> }
2021-01-25T09:57:12.986Z  Received 'zcl' data '{"address":21443,"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":17,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":16,"attrData":0},{"attrId":0,"dataType":16,"attrData":1}]},"endpoint":1,"linkquality":160,"groupID":null}'
2021-01-25T09:57:12.994Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:12.996Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 18' }
2021-01-25T09:57:12.999Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:13.001Z { logLevel: 'INFO ', log: 'EP EVT: Invalid event type' }
2021-01-25T09:57:14.671Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:14.673Z { logLevel: 'INFO ', log: 'Got bdb event 1' }
2021-01-25T09:57:14.675Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:14.677Z { logLevel: 'INFO ', log: 'ZCL_Task got event 1' }
2021-01-25T09:57:14.683Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:14.685Z { logLevel: 'INFO ', log: 'DATA: SEP=1 DEP=1 Profile=0104 Cluster=0006' }
2021-01-25T09:57:14.688Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:14.690Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 17' }
2021-01-25T09:57:14.695Z { msgCodeBytes: <Buffer 80 02>, msgLengthBytes: <Buffer 00 15>, checksumBytes: <Buffer 06>, msgPayloadBytes: <Buffer 00 01 04 00 06 01 01 02 53 c3 02 00 00 18 12 0a 00 80 20 02>, rssiBytes: <Buffer a0>, msgLengthOffset: -1 }
2021-01-25T09:57:14.696Z --> parsed frame �[1;34m>>>> DataIndication 0x8002 <<<<�[0m 
2021-01-25T09:57:14.699Z { status: 0, profileID: 260, clusterID: 6, sourceEndpoint: 1, destinationEndpoint: 1, sourceAddressMode: 2, sourceAddress: 21443, destinationAddressMode: 2, destinationAddress: 0, payload: <Buffer 18 12 0a 00 80 20 02> }
2021-01-25T09:57:14.706Z  Received 'zcl' data '{"address":21443,"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":18,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":32768,"dataType":32,"attrData":2}]},"endpoint":1,"linkquality":160,"groupID":null}'
2021-01-25T09:57:14.738Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:14.739Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 18' }
2021-01-25T09:57:14.752Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:14.754Z { logLevel: 'INFO ', log: 'EP EVT: Invalid event type' }
2021-01-25T09:57:20.291Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:20.293Z { logLevel: 'INFO ', log: 'Got bdb event 1' }
2021-01-25T09:57:20.296Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:20.298Z { logLevel: 'INFO ', log: 'ZCL_Task got event 1' }
2021-01-25T09:57:20.303Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:20.306Z { logLevel: 'INFO ', log: 'DATA: SEP=1 DEP=1 Profile=0104 Cluster=0006' }
2021-01-25T09:57:20.309Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:20.311Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 17' }
2021-01-25T09:57:20.316Z { msgCodeBytes: <Buffer 80 02>, msgLengthBytes: <Buffer 00 19>, checksumBytes: <Buffer a8>, msgPayloadBytes: <Buffer 00 01 04 00 06 01 01 02 53 c3 02 00 00 18 13 0a 00 00 10 00 00 00 10 01>, rssiBytes: <Buffer a0>, msgLengthOffset: -1 }
2021-01-25T09:57:20.318Z --> parsed frame �[1;34m>>>> DataIndication 0x8002 <<<<�[0m 
2021-01-25T09:57:20.321Z { status: 0, profileID: 260, clusterID: 6, sourceEndpoint: 1, destinationEndpoint: 1, sourceAddressMode: 2, sourceAddress: 21443, destinationAddressMode: 2, destinationAddress: 0, payload: <Buffer 18 13 0a 00 00 10 00 00 00 10 01> }
2021-01-25T09:57:20.327Z  Received 'zcl' data '{"address":21443,"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":19,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":16,"attrData":0},{"attrId":0,"dataType":16,"attrData":1}]},"endpoint":1,"linkquality":160,"groupID":null}'
2021-01-25T09:57:20.336Z --> parsed frame �[1;34m>>>> LOG 0x8001 <<<<�[0m 
2021-01-25T09:57:20.338Z { logLevel: 'INFO ', log: 'Entering cbZCL_EndpointCallback 17' }
2021-01-25T09:57:20.344Z { msgCodeBytes: <Buffer 80 02>, msgLengthBytes: <Buffer 00 19>, checksumBytes: <Buffer a8>, msgPayloadBytes: <Buffer 00 01 04 00 06 01 01 02 53 c3 02 00 00 18 13 0a 00 00 10 00 00 00 10 01>, rssiBytes: <Buffer a0>, msgLengthOffset: -1 }
2021-01-25T09:57:20.345Z --> parsed frame �[1;34m>>>> DataIndication 0x8002 <<<<�[0m 
2021-01-25T09:57:20.349Z { status: 0, profileID: 260, clusterID: 6, sourceEndpoint: 1, destinationEndpoint: 1, sourceAddressMode: 2, sourceAddress: 21443, destinationAddressMode: 2, destinationAddress: 0, payload: <Buffer 18 13 0a 00 00 10 00 00 00 10 01> }
2021-01-25T09:57:20.355Z  Received 'zcl' data '{"address":21443,"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":19,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":16,"attrData":0},{"attrId":0,"dataType":16,"attrData":1}]},"endpoint":1,"linkquality":160,"groupID":null}'

[fairecasoimeme]

Fixed

[G1K]

It seems to me that the sqn selects the device itself and it is possible that two different devices will send messages with one sqn in turn. Then such a message will be filtered out.

[fairecasoimeme]

Ok you're right. I added the short address to the variable.

[Hedda]

And what is the point of sending two identical messages via UART, is it possible to deduplicate at the firmware level?

Might it not be good with duplicated data for redundancy to better handle serial packet loss if you are using the adapter on a WiFi bridge and stream the raw data via a serial proxy server such as for example ser2net over a possibly unstable WiFi network?

I do not know about the ZiGate WiFi bridge connection works internally but the EmberZNet Serial Protocol (EZSP) that Silicon Labs based products use does not do a good job at handling the loss of serial packages (serial communication faults) which could be caused by WiFi interference if network packages are lost or if WiFi goes down.

Because of this, devs of the bellows library for zigpy has posted this warning against using Zigbee to WiFi bridges with EZSP:

https://github.com/zigpy/bellows#warning-about-zigbee-to-wifi-bridges

Warning about Zigbee to WiFi bridges

zigpy requires a robust connection between the zigpy radio library and the serial port of the Zigbee radio. With solutions such as ITEAD Sonoff ZBBridge or a Ser2Net serial proxy connection over a WiFi network it is expected to see NCP entered failed state. Requesting APP controller restart in the logs. This is a normal part of the operation and indicates there was a drop in communication which caused packet loss to occurred between the zigpy radio library and the Zigbee radio. The use of serial network proxies/bridges/servers over WiFi is therefore not recommended when wanting a stable Zigbee environment with zigpy.

[pipiche38]

firmware 31e