lwm2m: unexpected ENOMEM when adding observer

[etiennedm]

Describe the bug

I'm getting a hard to reproduce situation where the LwM2M engine cannot add new observers even though none are actually considered to be registered by the engine.

Context: network of low power sensors communicating through a Thread network to a LwM2M server running on a RPi.

The issue arises when there is a loss of connectivity with the LwM2M server, which can happen quite frequently. When the sensor eventually reconnects, the server sends observe requests for 7 resources. I suspect a problem when cleaning up old observers, resulting in a state where they are considered in use but are actually not being used. Using the lwm2m obs shell command, I get an empty output. However no new observer can be added, and the ENOMEM error points to a failure in engine_allocate_observer.

I have CONFIG_LWM2M_ENGINE_MAX_OBSERVER=20 to alleviate the issue, but eventually all nodes suffer from the ENOMEM error.

Regression

• This is a regression.

Steps to reproduce

I don't have a simple minimal sample to reproduce this issue, and I cannot reliably reproduce it myself. Lowering CONFIG_LWM2M_ENGINE_MAX_OBSERVER does make it happen more quickly though.

Relevant log output

Impact

Functional Limitation – Some features not working as expected, but system usable.

Environment

• OS: Linux
• Zephyr SDK 0.16.3
• SHA b7970cc

Additional Context

No response

[danieldegrasse]

@etiennedm can you add some log output or additional details to this issue if possible? Perhaps running with debug logging enabled?

[rlubos]

@etiennedm How do you handle the LWM2M_RD_CLIENT_EVENT_NETWORK_ERROR state in your application, do you call lwm2m_rd_client_stop() in such case?

I'm asking this because I had a hard time reproducing this issue, but all our examples do call lwm2m_rd_client_stop() in case the library reports an network error (which does a clean up on all allocated resources for the client session). I have noticed however, that if the lwm2m_rd_client_stop() isn't called, it's still possible to restart the client (no error on lwm2m_rd_client_start() call), which could lead to observers leak.

It doesn't seem right though that the LwM2M doesn't do the cleanup in case of fatal network errors so I've opened a PR with a fix: #92041
Can you verify if it helps in your case?

[SeppoTakalo]

@etiennedm out of curiosity, what kind of "loss of connectivity" we are talking about here?
Does it mean, that all CoAP retries are lost, or is is actually producing a socket error?

Any log output?

I have not used our LwM2M stack on Thread, but I have used other CoAP based clients on 6LoWPAN networks and it should be fine. One thing might hit you first is that default CoAP timeouts are way too fast for typical 802.15.4 networks. I would start experimenting with CONFIG_COAP_INIT_ACK_TIMEOUT_MS as high as it can take on typical DTLS handshake on that network. This is because on some network stack configurations, when DTLS sockets are used, the handshake starts only when first packet is sent.

[etiennedm]

I realize the bug report is lacking in the logs department. Unfortunately the only device for which I have 24/7 logs is connected to the Raspberry, very close to the Thread RCP node, and experiencing loss of connectivity much less frequently than the other 4 nodes. It does not show this behavior (or more accurately it gets rebooted every ~2 months when I recharge the lithium cell powering it, and by chance that's enough to avoid the issue).

@rlubos I originally copied the sample code, and it's indeed calling lwm2m_rd_client_stop() on a LWM2M_RD_CLIENT_EVENT_NETWORK_ERROR event.

@SeppoTakalo However I also have some code handling Thread state changes, with a is_connected boolean set based on the device role (1 for OT_DEVICE_ROLE_CHILD, OT_DEVICE_ROLE_ROUTER or OT_DEVICE_ROLE_LEADER and 0 for OT_DEVICE_ROLE_DISABLED or OT_DEVICE_ROLE_DETACHED). This is what I mean by "loss of connectivity".

And then based on this is_connected value I'm calling lwm2m_rd_client_start and lwm2m_rd_client_stop every 10 seconds (aka. the sampling period of the sensors on the board), relying on the LwM2M engine to not do anything most of the time when it's already started/stopped. So there is likely a window of time where the engine could have gone through a network error, and yet I call lwm2m_rd_client_start before lwm2m_rd_client_stop is called? This is far from the ideal way of doing things, but it was a quick and dirty POC that stayed that way 😬

I'll try to flash 2 out of the 5 devices with your PR @rlubos, and I'll also lower the LWM2M_ENGINE_MAX_OBSERVER value to the minimum required to increase the chances of observing the issue.

[rlubos]

I realize the bug report is lacking in the logs department. Unfortunately the only device for which I have 24/7 logs is connected to the Raspberry, very close to the Thread RCP node, and experiencing loss of connectivity much less frequently than the other 4 nodes. It does not show this behavior (or more accurately it gets rebooted every ~2 months when I recharge the lithium cell powering it, and by chance that's enough to avoid the issue).

Oh wow, didn't realize it takes that long to reproduce!

So there is likely a window of time where the engine could have gone through a network error, and yet I call lwm2m_rd_client_start before lwm2m_rd_client_stop is called?

If you do call lwm2m_rd_client_stop() in the callback on LWM2M_RD_CLIENT_EVENT_NETWORK_ERROR that shouldn't really be the case I think - we only set the engine state to ENGINE_IDLE after calling the callback, and that's a precondition for a sucessfull lwm2m_rd_client_start().

However, based on your description, I've checked the source code again for potential places where we change the engine state to IDLE w/o cleaning up the observers and I've identified one more problematic place when the leakage could take place. When deregistering, in case of network error we go straight to the IDLE state w/o cleaning up resources, that could be a problem as well.

I have updated my PR #92041 - please use the most recent commit in your testing instead.

[etiennedm]

Thanks for hunting this down! I tried to find potential clean up issues, but sadly I'm not familiar enough with the LwM2M subsystem to get anywhere.

2 devices are running on your PR @rlubos, the other 3 on the previous commit, let's see what it does!

[SeppoTakalo]

And then based on this is_connected value I'm calling lwm2m_rd_client_start and lwm2m_rd_client_stop every 10 seconds (aka. the sampling period of the sensors on the board), relying on the LwM2M engine to not do anything most of the time when it's already started/stopped. So there is likely a window of time where the engine could have gone through a network error, and yet I call lwm2m_rd_client_start before lwm2m_rd_client_stop is called? This is far from the ideal way of doing things, but it was a quick and dirty POC that stayed that way 😬

Three things that you should consider:

• If you call lwm2m_rd_client_stop(), make sure you have the deregister=false, otherwise the client tries to send deregistration message, and it takes a long time for CoAP retries to timeout and actually stop the client.
• Instead of stopping and starting, you could use lwm2m_engine_pause() when you know network is lost, and lwm2m_engine_resume() when you assume network is working again. This keeps the lifetime and registration statuses. We use it in our cellular lwm2m sample.
• Consider using DTLS Connection Identifier. I'm not sure if you already use it. If you pause and then resume, the CID allows client to be back on registered status with just one Coap message, instead of going through full DTLS handshake.

Examples, of pause-resume on our cellular LwM2M sample:

• When LTE connectivity is lost https://github.com/nrfconnect/sdk-nrf/blob/e82b8998f451e98348c6e72e2306469823e2f566/samples/cellular/lwm2m_client/src/main.c#L555
• When we regain the LTE connectivity https://github.com/nrfconnect/sdk-nrf/blob/e82b8998f451e98348c6e72e2306469823e2f566/samples/cellular/lwm2m_client/src/main.c#L702

Oh.. and last thing. To ensure that your state machine is really in sync with LwM2M state machine, only call the lwm2m_rd_client_start() after you have received DISCONNECTED or NETWORK_ERROR events. As show in the state diagram here: https://docs.zephyrproject.org/latest/connectivity/networking/api/lwm2m.html#lwm2m-engine-and-application-events

On typical network errors, the client tries to recover itself, so NETWORK_ERROR and DISCONNECTED events are the only ones that indicate that it has really stopped.
Those lwm2m_rd_client_start() and lwm2m_rd_client_stop() are not extremely robust on all corner cases. It is better if there is only one thread that calls those. If there are multiple system events that might call those, there is a big change of these kind of issues.

ps. I hope you also are using CONFIG_LWM2M_TICKLESS=y which makes the state machine to react changes almost immediately, instead of 500ms delay. Then you have fewer changes of going off-sync.

[etiennedm]

Thank you very much for theses great pieces of advice @SeppoTakalo! I didn't know about lwm2m_engine_pause() and lwm2m_engine_resume(), this sounds perfect for this use case. I'll take a closer look at the cellular samples, you're right, it's quite similar in spirit.

[etiennedm]

Hi, a quick update from the testing in progress: unfortunately the devices/firmware work quite well. Until this morning all devices behaved as expected. One device got stuck this morning, and it was running without your fix @rlubos. I'll keep you posted if I can gather more meaningful statistics.