Sleepy end device causing missed report of variable change

[Isaia F]

Greetings, i'm developing a custom sleepy end device whose role is to detect whether a certain event is occurring, this triggers the update (EDIT: via interrupt handler) of a custom cluster boolean attribute that is then reported to the coordinator, once the event stops being detected, the boolean attribute is then reset by means of a Zephyr timer.

I have noticed that, with the sleepy end device behavior configured, sometimes the device fails to report the change from "false" to "true", but then reports correctly the change back to false when the timer expires.

A check with a packet sniffer further confirmed the fact that the packet is simply not being sent.

How can i solve this issue?
Thanks in advance

EDIT: addendum
After setting up the project to log to RTT and checking more with a DK running the Shell sample as coordinator, i see the following:
-the sending of the report packet seems delayed by around 2-4 seconds (tested by counting the time between a led turning off, signaling the update of the attribute to false and the reception of the report)
-the RTT does not seem to grab all logs in a timely manner, sometimes losing or receiving LOG_INF in a delayed manner, i do not know if this is related

[Isaia F]

Hi Marte Myrvold 
I would reply directly to your comment but apparently the site has decided to not show me, no matter what, the button to reply to your message.

The SDK version is 1.9.1 as it still works with SES. As for a minimal project where such thing is reproduced... We'll try but we are in a bit of a time crunch unfortunately due to other projects. Could upload the current project or its source if you prefer but it's configured for a custom board.

[Marte Myrvold]

Hi,

If it is not too much work to change it to using a DK then you can upload it and I will test. Let me know if you want me to make the ticket private before you upload the project.

Best regards,

Marte

[Isaia F]

Hi,

We tried adding the delay as you said (sleepy end device behavior), but with both 100ms and 200ms of delay we still see the issue (especially if there has been a few second since the last activity, see below)

[00:04:19.021,240] <inf> zigbee.eprxzcl: Received ZCL command (7): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=10 disable_def_resp=0 manuf_code=void payload=[01001000] (7)
[00:04:19.021,301] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:04:19.021,392] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:04:32.698,425] <inf> zigbee.eprxzcl: Received ZCL command (8): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=11 disable_def_resp=0 manuf_code=void payload=[01001001] (8)
[00:04:32.698,516] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:04:32.698,577] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: True
[00:04:33.808,197] <inf> zigbee.eprxzcl: Received ZCL command (9): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=12 disable_def_resp=0 manuf_code=void payload=[01001000] (9)
[00:04:33.808,288] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:04:33.808,349] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:04:50.483,215] <inf> zigbee.eprxzcl: Received ZCL command (10): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=13 disable_def_resp=0 manuf_code=void payload=[01001001] (10)
[00:04:50.483,306] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:04:50.483,367] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: True
[00:04:51.996,063] <inf> zigbee.eprxzcl: Received ZCL command (11): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=14 disable_def_resp=0 manuf_code=void payload=[01001000] (11)
[00:04:51.996,124] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:04:51.996,215] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:05:05.606,964] <inf> zigbee.eprxzcl: Received ZCL command (12): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=15 disable_def_resp=0 manuf_code=void payload=[01001000] (12)
[00:05:05.607,055] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:05:05.607,116] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:05:32.332,641] <inf> zigbee.eprxzcl: Received ZCL command (13): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=16 disable_def_resp=0 manuf_code=void payload=[01001000] (13)
[00:05:32.332,702] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:05:32.332,763] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:05:39.913,085] <inf> zigbee.eprxzcl: Received ZCL command (14): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=17 disable_def_resp=0 manuf_code=void payload=[01001001] (14)
[00:05:39.913,146] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:05:39.913,238] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: True
[00:05:41.053,344] <inf> zigbee.eprxzcl: Received ZCL command (15): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=18 disable_def_resp=0 manuf_code=void payload=[01001000] (15)
[00:05:41.053,436] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:05:41.053,497] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:05:51.699,218] <inf> zigbee.eprxzcl: Received ZCL command (16): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=19 disable_def_resp=0 manuf_code=void payload=[01001000] (16)
[00:05:51.699,310] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:05:51.699,371] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:06:28.599,822] <inf> zigbee.eprxzcl: Received ZCL command (17): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=20 disable_def_resp=0 manuf_code=void payload=[01001001] (17)
[00:06:28.599,884] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:06:28.599,975] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: True
[00:06:29.739,257] <inf> zigbee.eprxzcl: Received ZCL command (18): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=21 disable_def_resp=0 manuf_code=void payload=[01001000] (18)
[00:06:29.739,349] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:06:29.739,410] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False
[00:06:40.387,390] <inf> zigbee.eprxzcl: Received ZCL command (19): src_addr=0xabb4(short) src_ep=10 dst_ep=64 cluster_id=0xabcd profile_id=0x0104 cmd_dir=1 common_cmd=1 cmd_id=0x0a cmd_seq=22 disable_def_resp=0 manuf_code=void payload=[01001000] (19)
[00:06:40.387,451] <inf> zigbee_shell_report: Received value updates from the remote node 0xabb4
[00:06:40.387,542] <inf> zigbee_shell_report:     Profile: 0x0104 Cluster: 0xabcd Attribute: 0x0001 Type: 16 Value: False

[Marte Myrvold]

Hi,

Did you verify that is_shaked was changed to true on the device when this happened? Are sure that this is not just the periodic attribute reporting? The way you have set up attribute reporting (using the zcl subscribe command) the attribute will also be reported periodically, so when enough time has passed since the last attribute reporting it will send a new attribute report even if the value has not changed in the meantime.

Best regards,

Marte

[Isaia F]

Hi,

Yes, the is_shaked was changed to true (the only thing that we changed was the modification you suggested, ie the k_sleep before setting to false). 
Also, checking the documentation for the zcl subscribe on command, it appears that if we do not put a min and max interval it will default to 1 and 60 seconds respectively.
While it's true we were convinced that not setting such parameters would instead result in the attribute being reported at each and every change, regardless of timing. The fact the "main" timeout timer is already 1 second long and there is an additional 200ms of delay for the true->false switch (so a time greater than 1 second) should not result in dropped frames. This is very odd and i'm starting to wonder if it might be a bug in the zboss stack itself

In any case, how can we configure the reporting command so to have any and all changes reported? (ie: an effective minimum reporting interval of 0 and a maximum reporting interval of infinity, meaning that unless there is a change it will not send an attribute reporting but if there is a change it will always send a report)?

EDIT: setting min and max reporting interval to 0 0 in the shell still resulted in the same issue

Thanks in advance

[Marte Myrvold]

Hi,

To configure reporting on only value change and not periodic you need to send a configure reporting command where the maximum reporting field is 0x0000 and the minimum reporting field is not 0xffff, e.g.:

zcl subscribe on 0x1234 10 0xabcd 0x0104 0x01 16 1 0

When I tested with this I saw even more cases of true not being reported. I will ask the developers if this might be a bug.

Best regards,

Marte

[Marte Myrvold]

Hi,

According to the development team the issue seems to be caused by using ZBOSS API outside of ZBOSS context, and the lack of reaction from ZBOSS side is because the thread remains suspended. Their suggestion is that you schedule the ZBOSS callback so the function that changes the attribute value is executed in the ZBOSS context. This also ensures that the ZBOSS thread is woken up immediately and this is processed without any additional delay.

Please be aware that there is a potential issue regarding modifying the variable value from multiple threads at the same time (dev_ctx.shake_attr.is_shaked).

Best regards,

Marte

[Isaia F]

So we should schedule a work responsible for changing the attribute (like with the timeout)? Seems feasible assuming the following interrupts check the state of is_shaked (or alternatively, a dummy variable toggled along with the scheduling) before scheduling the work in order to avoid repeated schedulings.

Though the part regarding "modifying the variable value from multiple threads at the same time" puzzles me, are you saying that having two different works for toggling the variable on and off respectively is not recommended? 


Edit: the use of the ZB_SCHEDULE_APP_CALLBACK macro worked wonderfully and now we see every single update as it should. We all thank you for your help and for your patience.