[BUG] thread/ipc3 fuzzer failure ?

[lgirdwood]

See log - look like IPC3 entry to a thread creation ?

https://github.com/thesofproject/sof/actions/runs/16903533368/job/47887834713?pr=10156

================== Job 1 exited with exit code 1 ============
INFO: Running with entropic power schedule (0xFF, 100).
INFO:        0 files found in ./fuzz_corpus
INFO: -max_len is not provided; libFuzzer will not generate inputs larger than 4096 bytes
INFO: A corpus is not provided, starting from an empty corpus
	NEW_FUNC[1/6]: 0x8185bc0 in posix_is_cpu_running /home/runner/work/sof/sof/workspace/zephyr/soc/native/inf_clock/soc.c:39
	NEW_FUNC[2/6]: 0x8284a30 in nsif_cpu0_irq_raised_from_sw /home/runner/work/sof/sof/workspace/zephyr/boards/native/native_sim/irq_handler.c:128
	NEW_FUNC[1/1]: 0x825f790 in comp_drivers_get /home/runner/work/sof/sof/workspace/sof/src/include/sof/audio/component_ext.h:430
	NEW_FUNC[1/7]: 0x823afc0 in ipc_glb_tplg_message /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1403
	NEW_FUNC[2/7]: 0x823b720 in ipc_glb_tplg_comp_new /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1254
	NEW_FUNC[1/1]: 0x823b340 in ipc_glb_dai_message /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:630
	NEW_FUNC[1/1]: 0x823b120 in ipc_glb_pm_message /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:785
	NEW_FUNC[1/1]: 0x823b1d0 in ipc_glb_comp_message /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1235
	NEW_FUNC[1/2]: 0x823bc50 in ipc_glb_tplg_comp_connect /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1369
	NEW_FUNC[2/2]: 0x8243c30 in ipc_comp_connect /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/helper.c:634
	NEW_FUNC[1/1]: 0x823b3b0 in ipc_glb_probe /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1151
	NEW_FUNC[1/1]: 0x823b250 in ipc_glb_stream_message /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:528
	NEW_FUNC[1/2]: 0x823b8e0 in ipc_glb_tplg_free /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1381
	NEW_FUNC[2/2]: 0x824a250 in ipc_comp_free /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc-helper.c:290
	NEW_FUNC[1/1]: 0x823cbf0 in ipc_pm_context_restore /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:704
	NEW_FUNC[1/1]: 0x823e940 in ipc_stream_trigger /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:438
	NEW_FUNC[1/1]: 0x823e530 in ipc_stream_pcm_free /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:354
	NEW_FUNC[1/1]: 0x823d8d0 in ipc_comp_value /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1192
	NEW_FUNC[1/1]: 0x823dc90 in ipc_stream_pcm_params /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:198
	NEW_FUNC[1/2]: 0x823c400 in ipc_glb_tplg_pipe_complete /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1358
	NEW_FUNC[2/2]: 0x8249e90 in ipc_pipeline_complete /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc-helper.c:227
	NEW_FUNC[1/5]: 0x8193eb0 in buffer_alloc /home/runner/work/sof/sof/workspace/sof/src/audio/buffers/comp_buffer.c:231
	NEW_FUNC[2/5]: 0x823c750 in ipc_glb_tplg_buffer_new /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1287
	NEW_FUNC[1/1]: 0x8243530 in ipc_buffer_free /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/helper.c:512
	NEW_FUNC[1/1]: 0x823cc60 in ipc_pm_context_size /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:649
	NEW_FUNC[1/1]: 0x8260d10 in rballoc_align /home/runner/work/sof/sof/workspace/sof/zephyr/lib/alloc.c:500
	NEW_FUNC[1/4]: 0x816bc80 in alloc_chunk /home/runner/work/sof/sof/workspace/zephyr/lib/heap/heap.c:212
	NEW_FUNC[2/4]: 0x816c5b0 in sys_heap_aligned_alloc /home/runner/work/sof/sof/workspace/zephyr/lib/heap/heap.c:310
	NEW_FUNC[1/28]: 0x816b6e0 in sys_heap_alloc /home/runner/work/sof/sof/workspace/zephyr/lib/heap/heap.c:264
	NEW_FUNC[2/28]: 0x818af80 in gcd /home/runner/work/sof/sof/workspace/sof/src/math/numbers.c:25
	NEW_FUNC[1/4]: 0x823f810 in ipc_msg_dai_config /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:603
	NEW_FUNC[2/4]: 0x823fcb0 in build_dai_config /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:557
	NEW_FUNC[1/12]: 0x819a7e0 in pipeline_new /home/runner/work/sof/sof/workspace/sof/src/audio/pipeline/pipeline-graph.c:111
	NEW_FUNC[2/12]: 0x819abc0 in memcpy_s /home/runner/work/sof/sof/workspace/sof/zephyr/include/rtos/string.h:40
	NEW_FUNC[1/1]: 0x823f180 in ipc_stream_position /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:391
	NEW_FUNC[1/1]: 0x8247470 in ipc_get_ppl_comp /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc-common.c:107
	NEW_FUNC[1/3]: 0x8240410 in ipc_probe_info /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:1109
	NEW_FUNC[2/3]: 0x824f950 in probe_get /home/runner/work/sof/sof/workspace/sof/src/include/sof/probe/probe.h:104
	NEW_FUNC[1/4]: 0x816a740 in sys_heap_free /home/runner/work/sof/sof/workspace/zephyr/lib/heap/heap.c:164
	NEW_FUNC[2/4]: 0x816a9a0 in free_chunk /home/runner/work/sof/sof/workspace/zephyr/lib/heap/heap.c:134
	NEW_FUNC[1/1]: 0x8182e80 in memcmp /home/runner/work/sof/sof/workspace/zephyr/lib/libc/minimal/source/string/string.c:221
	NEW_FUNC[1/8]: 0x819b230 in pipeline_free /home/runner/work/sof/sof/workspace/sof/src/audio/pipeline/pipeline-graph.c:218
	NEW_FUNC[2/8]: 0x819b580 in ipc_msg_free /home/runner/work/sof/sof/workspace/sof/src/include/sof/ipc/msg.h:90
	NEW_FUNC[1/2]: 0x823d300 in ipc_pm_gate /home/runner/work/sof/sof/workspace/sof/src/ipc/ipc3/handler.c:754
	NEW_FUNC[2/2]: 0x8261110 in pm_runtime_enable /home/runner/work/sof/sof/workspace/sof/zephyr/lib/pm_runtime.c:68
AddressSanitizer:DEADLYSIGNAL
=================================================================
==5555==ERROR: AddressSanitizer: SEGV on unknown address 0x00000000 (pc 0x0825febb bp 0xe76ff108 sp 0xe76ff050 T7)
==5555==The signal is caused by a WRITE memory access.
==5555==Hint: address points to the zero page.
    #0 0x825febb in k_sys_fatal_error_handler /home/runner/work/sof/sof/workspace/sof/zephyr/wrapper.c:346:19
    #1 0x8173928 in assert_post_action /home/runner/work/sof/sof/workspace/zephyr/lib/os/assert.c:43:2
    #2 0x8270906 in z_swap_irqlock /home/runner/work/sof/sof/workspace/zephyr/kernel/include/kswap.h:210:2
    #3 0x8270906 in z_swap /home/runner/work/sof/sof/workspace/zephyr/kernel/include/kswap.h:227:9
    #4 0x8270906 in z_impl_k_yield /home/runner/work/sof/sof/workspace/zephyr/kernel/sched.c:1079:2
    #5 0x8266ece in k_yield /home/runner/work/sof/sof/workspace/build-fuzz/zephyr/include/generated/zephyr/syscalls/kernel.h:184:2
    #6 0x8266ece in work_queue_main /home/runner/work/sof/sof/workspace/zephyr/kernel/work.c:766:4
    #7 0x8171262 in z_thread_entry /home/runner/work/sof/sof/workspace/zephyr/lib/os/thread_entry.c:48:2

[lgirdwood]

@dbaluta fyi - there is a lot of IPC3 in the fuzzer output, worth a look.

[lgirdwood]

This might be due to a west update, being investigated.

[lgirdwood]

@cgturner1 fyi

[cgturner1]

@cgturner1 fyi

talked to the zephyr team and they don't quite know what is wrong looking at the fuzzing failure logs.... as they don't usually run this level of IPC testing. If we think this is due to the an issue with zephyr is it possible to open a bug in the zephyr repo that describes the problem/issue?

[lgirdwood]

@serhiy-katsyuba-intel @cgturner1 I've taken a quick looks and it appears we are scheduling in ISR context.

void z_impl_k_yield(void)
{
	__ASSERT(!arch_is_in_isr(), "");

	SYS_PORT_TRACING_FUNC(k_thread, yield);

	k_spinlock_key_t key = k_spin_lock(&_sched_spinlock);

	runq_yield();

	update_cache(1);
	z_swap(&_sched_spinlock, key);
}

I cant see how this can happen, as we should also hit in real life on HW.
@serhiy-katsyuba-intel can you binary chop the west update to bisect to the correct Zephyr commit as I feel this may be the quickest way to root cause (as the current logs look quite complex).

[serhiy-katsyuba-intel]

@lgirdwood , @cgturner1 , bisection shows this commit zephyrproject-rtos/zephyr@5183fc5 breaks IPC3 fuzzer test.

[lyakh]

@serhiy-katsyuba-intel @cgturner1 I've taken a quick looks and it appears we are scheduling in ISR context.

@lgirdwood Do you mean that we are calling that function from an atomic context or that the function locks interrupts and then schedules? The latter is correct - switching to a different thread will then restore its interrupt state. If the former - where are we calling it that way?

[lgirdwood]

@lyakh I'm not sure whats going on as the fuzzer log is quite complex and I'm not sure exactly what parts of the code its running or its entry environment.

@dcpleung @cgturner1 will need your help here, zephyrproject-rtos/zephyr@5183fc5 is breaking the fuzzer (maybe a false positive on xtensa ??), needs someone with zephyr scheduling knowledge to comment.

[dcpleung]

That code path should not have been compiled/executed as Xtensa uses the switch mechanism (with CONFIG_USE_SWITCH enabled).

[lyakh]

That code path should not have been compiled/executed as Xtensa uses the switch mechanism (with CONFIG_USE_SWITCH enabled).

@dcpleung @lgirdwood I don't think the fuzzer test is built for Xtensa:

west build -d build-fuzz -b native_sim ...