A timer with 24-hour timeout fires immediately

[michal-narajowski]

Describe the bug
In Mesh implementation in net.c there is a ivu_timer that has a 24-hour timeout, yet it fires immediately causing invalid behavior of IV Update Procedure. After changing the timeout to 10 seconds the timer was behaving as expected. Possibly the large value of timeout is causing invalid behavior. I believe that this issue is related to the recent changes in k_timeout_t.

To Reproduce
Run MESH/NODE/IVU/BV-01-C test in PTS and follow the instructions.

It should be also possible to reproduce it by testing against another Zephyr node:
Provision two nodes. Enable IV Update test mode in both. Start IV Update procedure in one of them and observe the behavior of the other one.

I verified the invalid behavior by looking at debug logs.

Expected behavior
ivu_timer firing after 24 hour period.

Screenshots or console output

<snippet>
[00:00:17.298,980] <dbg> bt_mesh_beacon.secure_beacon_recv: net_idx 0x0000 iv_index 0x0000000b, current iv_index 0x0000000a
[00:00:17.298,980] <dbg> bt_mesh_net.bt_mesh_net_iv_update: IV Update state entered. New index 0x0000000b
[00:00:17.299,011] <dbg> bt_mesh_net.bt_mesh_net_beacon_update: NetIndex 0 Using current key
[00:00:17.299,041] <dbg> bt_mesh_net.bt_mesh_net_beacon_update: flags 0x02, IVI 0x0000000b
[00:00:17.299,530] <dbg> bt_mesh_net.ivu_refresh: IVU in Progress for 24 hours
[00:00:17.299,652] <dbg> bt_mesh_net.ivu_refresh: IVU in Progress for 48 hours
[00:00:17.299,865] <dbg> bt_mesh_net.ivu_refresh: IVU in Progress for 72 hours
[00:00:17.300,018] <dbg> bt_mesh_net.ivu_refresh: IVU in Progress for 96 hours
[00:00:17.300,048] <dbg> bt_mesh_net.bt_mesh_net_iv_update: Normal mode entered
[00:00:17.300,109] <dbg> bt_mesh_net.bt_mesh_net_beacon_update: NetIndex 0 Using current key
[00:00:17.300,109] <dbg> bt_mesh_net.bt_mesh_net_beacon_update: flags 0x00, IVI 0x0000000b
[00:00:17.300,567] <dbg> bt_mesh_beacon.beacon_send:
[00:00:17.300,567] <dbg> bt_mesh_beacon.secure_beacon_send:
[00:00:17.300,598] <dbg> bt_mesh_net.ivu_refresh: IVU Normal mode for 24 hours
[00:00:17.300,720] <dbg> bt_mesh_net.ivu_refresh: IVU Normal mode for 48 hours
[00:00:17.300,842] <dbg> bt_mesh_net.ivu_refresh: IVU Normal mode for 72 hours
[00:00:17.300,964] <dbg> bt_mesh_net.ivu_refresh: IVU Normal mode for 96 hours
</snippet>

Environment

• OS: Linux
• Toolchain: Zephyr SDK
• HW: nRF52840DK
• SHA: d96a1a5

[carlescufi]

@pabigot does this sound familiar?

[andyross]

Can you post the .config for the application, and an indication of where the timeout is being set, if you have it?

My blind guess is that this is an overflow bug in the code computing the timeout. If you have a 32 bit quantity that goes negative and construct a timeout out of it, the newer code will clamp to zero in a macro (the older code would just give you whatever junk was computed, cast to an unsigned value).

[michal-narajowski]

The bt_mesh.ivu_timer is initialized in subsys/bluetooth/mesh/net.c.
Here is the config file: config.txt

[pabigot]

It sounds familiar because (a) somewhere there's an issue that reported this well over a year ago; and (b) because we've been discussing it on slack. https://zephyrproject.slack.com/archives/C18PLHN8H/p1592386718046500

Ensuring the calculation was done with unsigned values, and converting to an absolute timeout, apparently didn't fix the problem. This should be reproduced in a standalone example to confirm there's no bug in absolute timeouts; then there are fixes needed to ensure that the transformation doesn't result in a signed intermediate. E.g. K_HOURS should not be scaling by a signed integer.

[pabigot]

@andyross This reproduces the problem on nordic hardware.

#include <zephyr.h>
#include <sys/printk.h>

#define INTERVAL K_HOURS(24)  // change to 18 and it works (nordic-specific boundary)

static struct k_delayed_work work;
static void do_work(struct k_work *wp)
{
	struct k_delayed_work *w = CONTAINER_OF(wp, struct k_delayed_work, work);

	printk("%" PRIx64 " now\n", k_uptime_get());
	k_delayed_work_submit(w, INTERVAL);
}

void main(void)
{
	k_delayed_work_init(&work, do_work);
	k_delayed_work_submit(&work, K_NO_WAIT);
	while (true) {
		k_sleep(K_HOURS(24));
	}
}

[andyross]

Cool, thanks. Reproducers are always the magic. Two spots were still 32 bit, fix submitted.

The constructor macros weren't actually the problem here, it was the dticks field that was wrong. And that's why it was subtle to reproduce: you needed to have a very long timeout inserted into the queue after an existing queued timeout.

[michal-narajowski]

I tested the fix and it works as expected. Well, I didn't wait for 24 hours but it doesn't fire immediately anymore :)

[andyross]

Excellent, thanks. As I read the bug, we were actually pretty lucky to have discovered it. The rollover was in a tick delta, which is below the clamping I mentioned earlier and in code that assumes unsigned numbers. Arbitrary rollovers would have produced arbitrary deltas, so the fact that it was expiring "immediately" was I think just dumb luck.