FRDM-K64F boot hang w/ mcuboot + lwm2m client

[mike-scott]

Using latest master, I can produce a boot hang on K64F when using mcuboot + the lwm2m client chain loaded from slot 0. The interesting bit is that IPv6 needs to be disabled.

Bisecting led to this commit:
1856e22#diff-23bba5938c8ac686f219f01f58478b9aR152

And if I change line 152 from:

update_cache(0);

to

update_cache(1);

It allows the boot to finish (not saying this is a fix, just stating that this makes the boot hang go away).

Even more curious, if I flash the lwm2m client directly and avoid mcuboot, this issue doesn't happen.

The thread that's hanging is started via k_work_q_start() here:
https://github.com/zephyrproject-rtos/zephyr/blob/master/subsys/net/ip/net_tc.c#L343

TBH, I don't understand the scheduler changes enough to really debug this further.

[mike-scott]

@andyross Looking for some guidance in the best way to debug this further.

[mike-scott]

This bug has a VERY racy feel to it. When I add printk for debugging it can make the problem go away as well.

[mike-scott]

Adding @agross-linaro for mild interest.

[andyross]

If I had to guess, it's likely a bad assumption in the app or maybe network code. The change to the scheduler there was that there were circumstances in the new scheduler (and apparently the older one?) where a thread at cooperative (i.e. non-preemptible) priority would release the CPU and switch to a different thread when it wasn't supposed to. Cooperative threads are per documentation not supposed to be descheduled until they deliberately pend or yield.

The change you made allows for any thread being added to the ready queue (i.e. basically everything -- threads being woken up, or having their priorities change, or being created, etc...) to preempt whatever was already running, which is wrong.

So... I'm guessing that somewhere there's an assumption that after a wakeup and/or thread creation, that the new high priority thread will have "already run", but it doesn't because the thread that is already running is at a cooperative priority. (And of course this kind of thing is absolutely going to be racy, which is exactly what you see).

Try listing out the threads in the app changing one at a time to a preemptible priority, and seeing if you can identify the specific spot where a thread is waking up and "not running right away as the app/library expects".

[andyross]

Oh, and the fix there might be as simple as stuffing a k_yield() call in to let the current thread chill for a bit.

[mike-scott]

There are only 2 other threads running when the work_q_start() is called. One is the main system thread.

[andyross]

I'm looking at this and getting stuck seeing how you could possible get a hang inside work_q_start() because of NON-preemption. Can you post the .config file for the app? Or just grep out anything with "PRIO" in it?

[mike-scott]

@andyross I agree that this bug makes no sense.

I tracked down where the init was hanging and ended up in net_tc.c work q init functions. I then looked at the work_q_main (thread entry function) for a work queue and this change seems to have made a difference:

diff --git a/kernel/work_q.c b/kernel/work_q.c
index 6121f2c3e..19148ec23 100644
--- a/kernel/work_q.c
+++ b/kernel/work_q.c
@@ -28,6 +28,7 @@ static void work_q_main(void *work_q_ptr, void *p2, void *p3)
 
                work = k_queue_get(&work_q->queue, K_FOREVER);
                if (!work) {
+                       k_yield();
                        continue;
                }

However, I'm not sure why. I've also tried adding a printk there and it doesn't seem to be hitting the if clause at all.

[mike-scott]

EDIT: I'm wrong it is coming back with NULL work:

***** Booting Zephyr OS 1.12.0-rc1 *****
[MCUBOOT] [INF] main: Starting bootloader
[MCUBOOT] [INF] boot_status_source: Image 0: magic=unset, copy_done=0xff, image_ok=0xff
[MCUBOOT] [INF] boot_status_source: Scratch: magic=unset, copy_done=0xe, image_ok=0xff
[MCUBOOT] [INF] boot_status_source: Boot source: slot 0
[MCUBOOT] [INF] boot_swap_type: Swap type: none
[MCUBOOT] [INF] main: Bootloader chainload address offset: 0x20000
[MCUBOOT] [INF] main: Jumping to the first image slot
[dev/eth_mcux] [DBG] eth_0_init: MAC 00:04:9f:87:c4:36
work:0x2000786c
work:0x2000786c
work:0x2000786c
work:0x00000000
work:0x00000000
work:0x00000000
work:0x00000000
[repeats endlessly]

[mike-scott]

Using a patch like this:

index 6121f2c3e..831224a17 100644
--- a/kernel/work_q.c
+++ b/kernel/work_q.c
@@ -27,6 +27,7 @@ static void work_q_main(void *work_q_ptr, void *p2, void *p3)
                k_work_handler_t handler;
 
                work = k_queue_get(&work_q->queue, K_FOREVER);
+printk("work:%p\n", work);
                if (!work) {
                        continue;
                }

[pfalcon]

Copied from #8012 (comment) :

Note those lines (if (!work) continue) were added in c1fa82b, for the purpose of supporting cancellation of work queue items. Cancellation is a valid usecase when k_queue_get() and friends can return NULL when called with K_FOREVER. If you have another case, similar to, #4358, it needs separate consideration.