Test suite mslab_threadsafe fails randomly

[ulfalizer]

Been seeing this in a few different unrelated PRs now:

1/1 mps2_an385                tests/kernel/mem_slab/mslab_threadsafe/kernel.memory_slabs FAILED: timeout
---out-2nd-pass/mps2_an385/tests/kernel/mem_slab/mslab_threadsafe/kernel.memory_slabs/handler.log---
***** Booting Zephyr OS v1.14.0-rc1-573-g2e89905f86 *****
Running test suite mslab_threadsafe
===================================================================
starting test - test_mslab_threadsafe
***** MPU FAULT *****
  Data Access Violation
  MMFAR Address: 0x0
***** Hardware exception *****
Current thread ID = 0x20000134
Faulting instruction address = 0x49ea
Fatal fault in ISR! Spinning...
---out-2nd-pass/mps2_an385/tests/kernel/mem_slab/mslab_threadsafe/kernel.memory_slabs/handler.log---
0 of 1 tests passed with 0 warnings in 84 seconds
+ sleep 10
+ /home/buildslave/src/github.com/zephyrproject-rtos/zephyr/scripts/sanitycheck --inline-logs --enable-coverage -N --only-failed --outdir=out-3nd-pass
JOBS: 12
Selecting default platforms per test case
Building testcase defconfigs...
1 tests selected, 91522 tests discarded due to filters
1/1 mps2_an385                tests/kernel/mem_slab/mslab_threadsafe/kernel.memory_slabs FAILED: timeout
---out-3nd-pass/mps2_an385/tests/kernel/mem_slab/mslab_threadsafe/kernel.memory_slabs/handler.log---
***** Booting Zephyr OS v1.14.0-rc1-573-g2e89905f86 *****
Running test suite mslab_threadsafe
===================================================================
starting test - test_mslab_threadsafe
***** MPU FAULT *****
  Data Access Violation
  MMFAR Address: 0x0
***** Hardware exception *****
Current thread ID = 0x200000b0
Faulting instruction address = 0x49ea
Fatal fault in ISR! Spinning...
---out-3nd-pass/mps2_an385/tests/kernel/mem_slab/mslab_threadsafe/kernel.memory_slabs/handler.log---
0 of 1 tests passed with 0 warnings in 83 seconds

[ulfalizer]

Haven't seen it in a while now. Not sure what changed.

[andyross]

There was a "nonatomic swap" fix that went in about a week ago that IIRC mslab would have tickled. This is one of the tests that does fail sporadically in CI, but it's definitely not failing reliably for me right now on unloaded systems, and I'm regularly running such tests to check now as part of #12553. Will close, please reopen if you see it.

[andrewboie]

I am able to reproduce this issue.
https://github.com/andrewboie/zephyr/tree/mslab-threadsafe-issue
reproduces with the qemu_x86_coverage target.
This is on x86 but the error is we get a pagefault when we try to execute a NULL address:

Running test suite mslab_threadsafe
===================================================================
START - test_mslab_threadsafe
 PASS - test_mslab_threadsafe
===================================================================
Test suite mslab_threadsafe succeeded
===================================================================
PROJECT EXECUTION SUCCESSFUL
E: Page fault at address 0x0 (error code 0x11)
E: Access violation: supervisor thread not allowed to execute
E:   PDE: 0x0000000000136827 Writable, User, Execute Enabled
E:   PTE: 0x8000000000000013 Writable, Supervisor, Execute Disable
E: EAX: 0x00154680, EBX: 0x00000000, ECX: 0x00000246, EDX: 0x00156060
E: ESI: 0x00000000, EDI: 0x00104766, EBP: 0x001489e8, ESP: 0x001489e4
E: EFLAGS: 0x00000206 CS: 0x0008 CR3: 0x0013a220
E: call trace:
E: EIP: 0x00000000
E: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
E: Current thread: 0x0013a128 (unknown)
E: Halting system

the page fault error is weird: there's a mapping at the NULL PTE. I just found that this is a problem in my PR with NULL ranges getting mapped, need to fix this and see if the issue persists.

I can confirm a few things:

• This situation is very timing sensitive.
• The similarity with the previous report is the testcase, timing sensitivity, and NULL memory access (albeit execution and not data access)
• My branch reproduces 100% of the time on my system. It also failed in CI when I sent out #. We are using icount, so my guess is that other code changes in my PR which might change timings are causing this to get unlucky in whatever race is going on, and since it's icount execution is deterministic; it either always works or it doesn't.
• I haven't completely ruled out an issue in my PR being the culprit
• Doesn't reproduce in any other build target
• Extremely minor changes to the tmslab_api() function cause the crash to go away. like adding a printk() at the end, or removing the if (block[i]) check and freeing the block unconditionally, or changing the timeout arg to k_mem_slab_alloc() from TIMEOUT to K_FOREVER. It's that subtle.
• The crash is always one of the tdata threads. The stack is almost empty save for a memory address inside tmslab_api.
• I have not been able to figure out yet where we jumped to NULL from, but I do know that the crash happens after every statement in tmslab_api() has run. I made a change to use k_thread_join() in the test case on every child thread and these all succeed (see patch linked below)
• There's no stack overflows and we're not re-using thread objects

I thought I was going insane until I found this GH ticket.

I have a cleanup patch: andrewboie@9c4f699
there are comments that show where you can disturb the timings. Both branches I linked here reproduce the problem.

[andrewboie]

I think I can rule out any changes in my PR, nothing should be accessing any memory in the NULL page. This does seem like this obscure bug popping up again because of very subtle timing changes, perhaps this issue requires a timer interrupt at a bad time?

I don't have time right now to dive deeper, but leaving this open. I submitted a patch which cleans up the test code a little and adds a delay which makes the problem stop failing the test. #26883