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]

Addendum: the ncs-updates folder contains a few additions to the ncs folder, namely to handles the lis2dw12 and the connection reset button ( i can't edit my post because the button won't show on neither chrome or firefox)


Addendum to the addendum: we managed to flash a coordinator on a nrf52833dk and configured our end device in the following ways for testing (same project as we sent in the tgz)

When configured as End Device (not Sleepy) it behaved even worse when it came to sending the report frames false->true
In Router Mode however it behaved as expected (reliably sending the reporting frame every change in the parameter), unfortunately the consumption in router mode is far too high for our purposes.

[Marte Myrvold]

Hi,

How is the device sending the attribute to the coordinator? Does the coordinator subscribe to attribute reports on value change, or is there something else triggering the attribute report? I could not find anything regarding this in the project code. I am testing the project and it prints that is_shaked is changed to 1 and back to 0 again, but no packets are sent from the device.

Best regards,

Marte

[Isaia F]

Hi, 

The device should update the variable, and it's configured in the custom cluster as a reportable attribute

To test we used a DK with the Shell sample and configured the reporting.

Below is an example of what we inputted in the shell terminal to configure the reporting. So i suppose the answer is "the coordinator subscribes to the attribute".

uart:~$ zdo mgmt_lqi 0000
[idx] ext_pan_id ext_addr short_addr flags permit_join depth lqi
[ 0] f4ce36bc41dcdf74 f4ce364145c4c951 0x2541 0x15 0 1 172
ZDO request 1 complete
Done
uart:~$ zdo bind on f4ce364145c4c951 10 f4ce36bc41dcdf74 64 0xabcd 0x2541
Done
uart:~$ zcl subscribe on 0x2541 10 0xabcd 0x0104 0x0001 16

[Marte Myrvold]

Hi,

Thank you for clarifying. 

I used this command when testing, but at first it looked like the device only reported periodically. I see now that it reports both periodically and when the value is changed.

I believe I managed to reproduce the issue. Sometimes it did not send true even if I had pressed the button and saw in the log that it was changed. At least on my side the issue seemed to be that the attribute changed back again to false so quickly that the change happened before the attribute was sent, causing only false to be sent. When I added a small timer, k_sleep(K_MSEC(100)), before changing the attribute back to false then I did not see the issue anymore. Does it sound like this might be the reason for the problem on your side as well? I added the timer just after checking if is_shaked is true and before setting it to false with ZB_ZCL_SET_ATTRIBUTE.

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.