LwM2M Composite Observer attributes handling

[alanthompsonch]

Summary

Introduction

A composite observer sends all its observed paths at once. When this happens is defined by the attributes of the observed objects / resources and their instances. There is currently some behaviour that goes against the specification.

Current situation

In a composite observer, attributes are currently handled globally instead of individually. For pmax this doesn't matter, since the update then just triggers as soon as the first pmax hits. However, for pmin it leads to undesired behaviour. How this current behaviour manifests is described here:

Attached you can find a file with the client side uart logs. The server sets 3 observers, one for a button that enables us to trigger a registration update manually (min = 1, max = 135691200), one for the FOTA state to enable a clean FOTA (min = 1, max = 135691200) and the composite observer where all observers have min = 135691200, max = 135691200. I have also tested min = 59 due to this line from the specification:
It is the responsibility of the LwM2M Server to ensure that the Minimum and Maximum Period Attributes attached to observed resources follow the rules defined in Section 5.1.2. Attributes Classification. For example, the Minimum Period Attributes attached to targeted resources must be less than the Maximum Period Attributes attached to all targeted resources

Only our value of interest (voltage value: /3316/0/5700) has its default pmin / pmax overwritten to min=30 max=60. Since it's not updated, an update is triggered due to pmax after 60. Then RSS updates (/4/0/2), which for some reason triggers a new notify message after pmin of the /3316/0/5700 value. same thing happens if any value changes before or during the voltage value's pmin pmax window. See the device logs:

[00:00:09.715,240] <inf> app_lwm2m_client: LwM2M is connecting to server
[00:00:12.562,072] <inf> lwm2m_security: Requesting LTE and GNSS online
[00:00:14.551,635] <dbg> app_lwm2m_client: lwm2m_lte_reg_handler_notify: LTE NW status: 2
[00:00:14.551,696] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/0, buf:0x200340df, len:1
[00:00:15.239,135] <inf> lwm2m_security: Modem connection restored
[00:00:15.239,746] <dbg> app_lwm2m_client: lwm2m_lte_reg_handler_notify: LTE NW status: 1
[00:00:15.240,325] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/0/2/0, level 3, buf:0x2002d5e3, buflen:1
[00:00:15.240,447] <inf> app_lwm2m_client: LwM2M is connecting to server
[00:00:15.387,054] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/4, buf:0x20019f2a, len:13
[00:00:15.387,115] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/7, buf:0x2001a1ca, len:12
[00:00:15.387,176] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:3/0/3, buf:0x2001a402, len:18
[00:00:15.387,207] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/8, buf:0x2003415c, len:4
[00:00:15.387,268] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/9, buf:0x2003415e, len:2
[00:00:15.387,329] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/10, buf:0x2003415e, len:2
[00:00:15.387,359] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/12, buf:0x2003415e, len:2
[00:00:15.566,009] <inf> net_lwm2m_engine: Connected, sock id 2
[00:00:15.566,589] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x2002d608, buflen:4
[00:00:15.567,382] <dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [xx.xx.xxx.xxx]
[00:00:15.569,244] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 8
[00:00:15.666,229] <dbg> net_lwm2m_rd_client: do_registration_reply_cb: Registration callback (code:2.1)
[00:00:15.667,022] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x2002d470, buflen:4
[00:00:15.668,243] <dbg> app_lwm2m_client: rd_client_event: Registration complete
[00:00:15.668,395] <inf> net_lwm2m_rd_client: Registration Done (EP='afXVWHY62F')
[00:00:15.668,579] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124d8 handled and removed
[00:00:15.668,640] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:00:15.669,311] <inf> app_lwm2m_client: LwM2M is connected to server
[00:00:15.669,342] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x2002f9c8, buflen:4
[00:00:15.669,891] <inf> app_lwm2m_client: Obtained date-time from modem
[00:00:15.669,952] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:3/0/13, buf:0x2002e07c, len:4
[00:00:15.748,229] <inf> lwm2m_cellconn: PSM timer 216000 s, bits: 01000110
[00:00:15.948,028] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 3347/0/5518/0(3)
[00:00:15.948,089] <dbg> net_lwm2m_observation: engine_observe_node_init: token:'737e8676ad56d19f' addr:xx.xx.xxx.xxx
[00:00:15.965,728] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 5/0/3/0(3)
[00:00:15.965,820] <dbg> net_lwm2m_observation: engine_observe_node_init: token:'538f89e15e5c0e26' addr:xx.xx.xxx.xxx
[00:00:16.055,999] <dbg> net_lwm2m_message_handling: lwm2m_engine_default_content_format: No accept option given. Assume SenML CBOR.
[00:00:16.056,091] <dbg> net_lwm2m_observation: lwm2m_write_attr_handler: Add pmin to 1
[00:00:16.056,121] <dbg> net_lwm2m_observation: lwm2m_write_attr_handler: Add pmax to 135691200
[00:00:16.066,955] <dbg> net_lwm2m_message_handling: lwm2m_engine_default_content_format: No accept option given. Assume SenML CBOR.
[00:00:16.067,108] <dbg> net_lwm2m_observation: lwm2m_write_attr_handler: Add pmin to 1
[00:00:16.067,138] <dbg> net_lwm2m_observation: lwm2m_write_attr_handler: Add pmax to 135691200
[00:00:16.083,679] <dbg> net_lwm2m_message_handling: lwm2m_engine_default_content_format: No accept option given. Assume SenML CBOR.
[00:00:16.083,801] <dbg> net_lwm2m_observation: lwm2m_write_attr_handler: Add pmin to 30
[00:00:16.083,862] <dbg> net_lwm2m_observation: lwm2m_write_attr_handler: Add pmax to 60
[00:00:17.806,182] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 3/0/7/0(3)
[00:00:17.806,243] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 4/0/0/0(3)
[00:00:17.806,274] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 4/0/2/0(3)
[00:00:17.806,274] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 3303/0/5700/0(3)
[00:00:17.806,304] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 3303/1/5700/0(3)
[00:00:17.806,304] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 3304/0/5700/0(3)
[00:00:17.806,335] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 3304/1/5700/0(3)
[00:00:17.806,365] <dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 3316/0/5700/0(3)
[00:00:17.806,427] <dbg> net_lwm2m_observation: engine_observe_node_init: token:'553cb3ba239e32a5' addr:xx.xx.xxx.xxx
[00:00:19.569,580] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:00:21.811,126] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:00:21.811,187] <inf> lwm2m_rai: RAI enabled
[00:00:21.820,281] <dbg> app_lwm2m_client: rd_client_event: Queue mode RX window closed
[00:00:39.887,023] <inf> app_lwm2m_client: Modem Enter PSM, time 215983950
[00:01:17.806,762] <dbg> net_lwm2m_message_handling: generate_notify_message: [AUTO] NOTIFY MSG START: (Composite)) token:'553cb3ba239e32a5' [xx.xx.xxx.xxx] 77806
[00:01:17.809,417] <dbg> net_lwm2m_message_handling: generate_notify_message: NOTIFY MSG: SENT
[00:01:17.809,722] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:17.822,082] <dbg> app_lwm2m_client: rd_client_event: Registration update started
[00:01:17.922,668] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 11
[00:01:17.922,698] <dbg> net_lwm2m_engine: lwm2m_engine_connection_resume: Resume suspended connection
[00:01:17.923,278] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x2002d610, buflen:4
[00:01:17.923,431] <dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [xx.xx.xxx.xxx]
[00:01:17.932,495] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 12
[00:01:18.072,631] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/2, buf:0x200341b6, len:2
[00:01:18.072,814] <dbg> net_lwm2m_observation: lwm2m_notify_observer_path: NOTIFY EVENT 4/0/2
[00:01:19.855,041] <inf> net_lwm2m_rd_client: Update callback (code:2.4)
[00:01:19.855,102] <dbg> app_lwm2m_client: rd_client_event: Registration update complete
[00:01:19.855,224] <inf> net_lwm2m_rd_client: Update Done
[00:01:19.855,407] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124f0 handled and removed
[00:01:19.855,468] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:19.912,139] <dbg> net_lwm2m_message_handling: notify_message_reply_cb: NOTIFY ACK type:2 code:0.0 reply_token:'553cb3ba239e32a5'
[00:01:19.912,353] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124d8 handled and removed
[00:01:21.932,861] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:23.857,391] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:23.866,485] <dbg> app_lwm2m_client: rd_client_event: Queue mode RX window closed
[00:01:38.075,225] <inf> app_lwm2m_client: Modem Enter PSM, time 215983950
[00:01:47.806,884] <dbg> net_lwm2m_message_handling: generate_notify_message: [MANUAL] NOTIFY MSG START: (Composite)) token:'553cb3ba239e32a5' [xx.xx.xxx.xxx] 107806
[00:01:47.809,539] <dbg> net_lwm2m_message_handling: generate_notify_message: NOTIFY MSG: SENT
[00:01:47.809,844] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:47.822,204] <dbg> app_lwm2m_client: rd_client_event: Registration update started
[00:01:47.922,790] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 11
[00:01:47.922,821] <dbg> net_lwm2m_engine: lwm2m_engine_connection_resume: Resume suspended connection
[00:01:47.923,400] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x2002d610, buflen:4
[00:01:47.923,553] <dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [xx.xx.xxx.xxx]
[00:01:47.932,647] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 12
[00:01:49.689,697] <inf> net_lwm2m_rd_client: Update callback (code:2.4)
[00:01:49.689,758] <dbg> app_lwm2m_client: rd_client_event: Registration update complete
[00:01:49.689,849] <inf> net_lwm2m_rd_client: Update Done
[00:01:49.690,063] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124f0 handled and removed
[00:01:49.690,124] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:49.767,761] <dbg> net_lwm2m_message_handling: notify_message_reply_cb: NOTIFY ACK type:2 code:0.0 reply_token:'553cb3ba239e32a5'
[00:01:49.767,974] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124d8 handled and removed
[00:01:51.932,464] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:53.691,986] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:01:53.701,080] <dbg> app_lwm2m_client: rd_client_event: Queue mode RX window closed
[00:02:07.893,737] <inf> app_lwm2m_client: Modem Enter PSM, time 215983950
[00:02:20.310,272] <inf> hw_watchdog: feeding hw_watchdog
[00:02:47.806,365] <dbg> net_lwm2m_message_handling: generate_notify_message: [AUTO] NOTIFY MSG START: (Composite)) token:'553cb3ba239e32a5' [xx.xx.xxx.xxx] 167806
[00:02:47.809,020] <dbg> net_lwm2m_message_handling: generate_notify_message: NOTIFY MSG: SENT
[00:02:47.809,326] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:02:47.821,685] <dbg> app_lwm2m_client: rd_client_event: Registration update started
[00:02:47.921,295] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 11
[00:02:47.921,325] <dbg> net_lwm2m_engine: lwm2m_engine_connection_resume: Resume suspended connection
[00:02:47.921,905] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x2002d610, buflen:4
[00:02:47.922,058] <dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [xx.xx.xxx.xxx]
[00:02:47.931,121] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 12
[00:02:47.997,497] <dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/2, buf:0x200341b6, len:2
[00:02:47.997,711] <dbg> net_lwm2m_observation: lwm2m_notify_observer_path: NOTIFY EVENT 4/0/2
[00:02:49.850,280] <inf> net_lwm2m_rd_client: Update callback (code:2.4)
[00:02:49.850,341] <dbg> app_lwm2m_client: rd_client_event: Registration update complete
[00:02:49.850,433] <inf> net_lwm2m_rd_client: Update Done
[00:02:49.850,616] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124f0 handled and removed
[00:02:49.850,708] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:02:49.960,083] <dbg> net_lwm2m_message_handling: notify_message_reply_cb: NOTIFY ACK type:2 code:0.0 reply_token:'553cb3ba239e32a5'
[00:02:49.960,266] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124d8 handled and removed
[00:02:51.931,762] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:02:53.852,294] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:02:53.861,419] <dbg> app_lwm2m_client: rd_client_event: Queue mode RX window closed
[00:03:08.072,143] <inf> app_lwm2m_client: Modem Enter PSM, time 215983950
[00:03:17.806,823] <dbg> net_lwm2m_message_handling: generate_notify_message: [MANUAL] NOTIFY MSG START: (Composite)) token:'553cb3ba239e32a5' [xx.xx.xxx.xxx] 197806
[00:03:17.809,478] <dbg> net_lwm2m_message_handling: generate_notify_message: NOTIFY MSG: SENT
[00:03:17.809,783] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:03:17.822,143] <dbg> app_lwm2m_client: rd_client_event: Registration update started
[00:03:17.922,729] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 11
[00:03:17.922,760] <dbg> net_lwm2m_engine: lwm2m_engine_connection_resume: Resume suspended connection
[00:03:17.923,339] <dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x2002d610, buflen:4
[00:03:17.923,492] <dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [xx.xx.xxx.xxx]
[00:03:17.932,556] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 12
[00:03:19.848,602] <inf> net_lwm2m_rd_client: Update callback (code:2.4)
[00:03:19.848,663] <dbg> app_lwm2m_client: rd_client_event: Registration update complete
[00:03:19.848,785] <inf> net_lwm2m_rd_client: Update Done
[00:03:19.848,968] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124f0 handled and removed
[00:03:19.849,029] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:03:19.916,992] <dbg> net_lwm2m_message_handling: notify_message_reply_cb: NOTIFY ACK type:2 code:0.0 reply_token:'553cb3ba239e32a5'
[00:03:19.917,175] <dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x200124d8 handled and removed
[00:03:21.932,678] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:03:23.851,226] <dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9
[00:03:23.860,321] <dbg> app_lwm2m_client: rd_client_event: Queue mode RX window closed
[00:03:38.065,795] <inf> app_lwm2m_client: Modem Enter PSM, time 215983950

Describe the solution you'd like

Specified behaviour

The observer update should be triggered when any resource fullfills its individual trigger conditions. If the path /3316/0/5700 (voltage sensor value) has a short pmin but doesn't change, the composite observer update should not trigger until any of the other conditions are met.

Also, with the implementation of the st, gt and lt attributes (#92097), these should also be considered in this. So the voltage value should trigger the composite observer update if it has an st attribute of 5 set and changes by more than 5. The humidity sensor value changing by more than 5 should not trigger the update unless it has the same step attribute set itself.

Alternatives

This issue proposes an enhancement to bring the lwM2M engine closer to specification. No alternatives, really, except for leaving it as is.

Additional Context

No response

[rlubos]

Also, with the implementation of the st, gt and lt attributes (#92097), these should also be considered in this. So the voltage value should trigger the composite observer update if it has an st attribute of 5 set and changes by more than 5. The humidity sensor value changing by more than 5 should not trigger the update unless it has the same step attribute set itself.

@alanthompsonch Have you observed any undesired behavior wrt st/gt/lt attributes handling? Unless I miss something, those attributes are implemented exactly the way you descirbe, i.e. attributes are considered individually for each updated resource.

[rlubos]

CC @SeppoTakalo
So for composite observers, we currently determine pmin and pmax as the lowest value set from all composite observer paths:

zephyr/subsys/net/lib/lwm2m/lwm2m_observation.c

Line 469 in 366d45f

pmin = MIN(pmin, nattrs->pmin);

This definitely makes sense for pmax - we want to send notification no later then the shortest pmax period set for resources in the path, but for pmin? I think that when a resource is updated we should consider pmin individually just for the modified resource - if some other resource in the observer path has some lower pmin value does not mean we need to send the notification at pmin-time if that resoruce does not change. We should stick to the pmin set on the updated resource or the pmax value.

[alanthompsonch]

Also, with the implementation of the st, gt and lt attributes (#92097), these should also be considered in this. So the voltage value should trigger the composite observer update if it has an st attribute of 5 set and changes by more than 5. The humidity sensor value changing by more than 5 should not trigger the update unless it has the same step attribute set itself.

@alanthompsonch Have you observed any undesired behavior wrt st/gt/lt attributes handling? Unless I miss something, those attributes are implemented exactly the way you descirbe, i.e. attributes are considered individually for each updated resource.

No, I have not observed any undesired behaviour, I have not gotten around to testing the new release yet. It will surely be very useful in the future though; thanks for your work on this :)

The request would therefore just be making pmin per resource instead of taking the lowest pmin for all observer paths.

[rlubos]

I've opened #93508 with change proposal for pmin handling - when evaluating the notification criteria, LwM2M lib will now take the pmin configured for the updated resource into account (if set) and use it if the value is higher than the minimal pmin evaluated for the observer. Apart from manual testing I've ran the interop tests, seems to work fine.