Kernel: panic triggered by dash/oksh, and also coredumps from SIGCHLD

[oskar-skog]

crash.sh

Run with dash crash.sh. *1 It may take a few tries. If it takes more than five, try rebooting, it seems like SerenityOS can occasionally be stubbornly stable.

Tracebacks:
dash-x86_64-1.txt dash-x86_64-2.txt dash-x86_64-3.txt
oksh-x86_64-1.txt
dash-aarch64-1.txt dash-aarch64-2.txt dash-aarch64-3.txt
dash-riscv64-1.txt dash-riscv64-2.txt
oksh-riscv64-1.txt
combined.txt

The riscv64 tracebacks are maybe due to a different issue? It crashes suspiciously quickly for how slow the emulation is and are the only ones with Kernel::SpinlockLocker<Kernel::RecursiveSpinlock<(Kernel::LockRank)0> >::~SpinlockLocker()

The reproducer can probably be reduced further. It no longer depends on Python or my janky code.

My /bin/sh is a symlink to dash on my system, but I don't think this is important for reproducing the crashes.

The original script used to cause a panic consistently: almost always early in the 2nd invocation. But I believe that may just have been pure chance.

Discord thread: https://discord.com/channels/830522505605283862/830522505605283866/1450929276697313350

*1
Also works with oksh, but dash seems to be by far the most crashy. Not sure about bash. Zsh is a PITA to get working correctly and doesn't seem to cause a panic. Shell --posix doesn't run the script correctly and therefore does way less work than the other shells.

[oskar-skog]

If you revert some recent signal handling fixes, it stops panicking.

But you then get some weird segfaults on the first instruction of the signal trampoline.
It seems to be extremely rare for it to happen naturally, but can be triggered by me being impatient.
Edit: Reverting to the old signal handling is not necessary, they can still happen but are apparently more rare
than the coredumps from SIGCHLD.

I think this is what I did when I got the weird segfaults:

1. Start the script
2. Try to ^C, but it doesn't work
3. ^Z
4. ps and kill -TERM ...
5. fg to make it no longer be in a stopped state
6. It somehow didn't die, or at least the shell thinks so, so I give it another ^C

Or at least these are steps I took more recently when I was back on the main/master branch to work on the reproducer.
There the results are a bit different: dash got coredumped by SIGCHLD.

One example of coredump from SIGCHLD, not sure if it was provoked or occurred naturally:
syscallfrom +0x4a intowaitproc (call waitpid@plt) in src/jobs.c`.
986_dash_backtrace.txt waitproc.c.txt waitproc.s.txt

[implicitfield]

I saw something like this happen once by just booting up the system (but I could never get it to happen again). I kind of hoped #26483 fixed that, but well, it obviously didn't.

So the problem is that we're entering (and eventually exiting) a trap while we're already exiting one. This seems to happen thanks to a page fault in copy_to_user (otherwise I don't see how that call stack would happen).

Preferably we wouldn't be page faulting while in an IRQ-like context like this, not sure how to prevent that though (since this happens as a result of trying to access the userspace stack. Would be nice to know how other OSes handle this I guess).

No idea about the segfaults here, the scheduler-driven signal dispatching is different enough that it's hard to tell if this is something specific to that or not.

[oskar-skog]

I've found out that the coredump from SIGCHLD happened during a syscall in the waitpid function. I've added traceback and code snippets in the above comment.

[implicitfield]

Haven't seen any kernel panics so far while testing with the fixes from #26491 (with both oksh and dash). The SIGCHLD still happens, though I got a different backtrace (interestingly something seems to have also trashed the stack pointer, which is probably related):

69.453 [#0 dash(48:48)]: Terminating dash(48) due to signal 15
69.457 [#0 dash(48:48)]: Invalid stack pointer: 137742450416
69.457 [#0 dash(48:48)]: Terminating dash(48) due to signal 17
69.457 [#0 Finalizer Task(8:8)]: Backtrace:
0x00000000deadc0de  Kernel::ProcessorBase::switch_context(Kernel::Thread*&, Kernel::Thread*&) + 0xda
0x00000000deadc0de  Kernel::Scheduler::context_switch(Kernel::Thread*) + 0xff
0x00000000deadc0de  Kernel::Scheduler::pick_next() + 0xaf
0x00000000deadc0de  Kernel::Scheduler::yield() + 0x9b
0x00000000deadc0de  Kernel::Thread::die_if_needed() + 0x106
0x00000000deadc0de  syscall_handler + 0xaa
0x00000000deadc0de  syscall_entry + 0x54
[snip]
69.845 CrashReporter(660:661): --- Backtrace for thread #0 (TID 48) ---
69.845 CrashReporter(660:661): 0x0000001e894f9056: [/usr/lib/libsystem.so] syscall3 +0x16 (syscall.cpp:29)
69.845 CrashReporter(660:661): 0x00000000f9b7739a: [/usr/lib/libc.so] read +0x2a (syscall.h:40 => unistd.cpp:386)
69.850 CrashReporter(660:661): 0x000000076e5a8323: [/usr/local/bin/dash] expbackq +0x133 ()
69.850 CrashReporter(660:661): 0x000000076e5a6eb9: [/usr/local/bin/dash] argstr +0x2f9 ()
69.850 CrashReporter(660:661): 0x000000076e5a6aa2: [/usr/local/bin/dash] expandarg +0x42 ()
69.850 CrashReporter(660:661): 0x000000076e5a3ab3: [/usr/local/bin/dash] evalcommand +0x2b3 ()
69.854 CrashReporter(660:661): 0x000000076e5a3631: [/usr/local/bin/dash] evaltree +0x211 ()
69.854 CrashReporter(660:661): 0x000000076e5ad7b2: [/usr/local/bin/dash] cmdloop +0x122 ()
69.854 CrashReporter(660:661): 0x000000076e5ad626: [/usr/local/bin/dash] main +0x296 ()
69.854 CrashReporter(660:661): 0x000000076e5a11d6: [/usr/local/bin/dash] _entry +0x26 (crt0.cpp:47)

[oskar-skog]

I believe I must have been mistaken about the origin of the traceback for the SIGCHLD case I mentioned above.

I'm testing your PR on x86_64, and I haven't had a single panic in many many hours.
I've had only one case of spontaneous SIGCHLD coredump, and /that/ one was during a waitid syscall.
And one "provoked" SIGCHLD coredump that looks essentially identical to yours, only the offsets into the functions are slightly different.

Console log from the naturally occurring, nothing happened before "Invalid stack pointer".

2294.565 [#0 dash(55:55)]: Invalid stack pointer: 137730260616
2294.565 [#0 dash(55:55)]: Terminating dash(55) due to signal 17
2294.583 [#0 Finalizer Task(8:8)]: Backtrace:
0x00000000deadc0de  Kernel::ProcessorBase::switch_context(Kernel::Thread*&, Kernel::Thread*&) + 0x172
0x00000000deadc0de  Kernel::Scheduler::context_switch(Kernel::Thread*) + 0x14e
0x00000000deadc0de  Kernel::Scheduler::pick_next() + 0xd3
0x00000000deadc0de  Kernel::Scheduler::yield() + 0x5b
0x00000000deadc0de  Kernel::Thread::die_if_needed() + 0x163
0x00000000deadc0de  syscall_handler + 0x448
0x00000000deadc0de  syscall_entry + 0x54
0x0000001f03a36892  /usr/local/bin/dash: .text + 0xd892
.....
0x0000001f03a2c2e5  /usr/local/bin/dash: .text + 0x32e5
2294.768 [#0 Finalizer Task(8:8)]: Generating coredump for pid: 55
2295.009 CrashDaemon(37): New coredump file: /tmp/coredump/dash_55_1766249732
2302.654 CrashReporter(2852:2885): Generating backtrace took 1862 ms
2302.735 CrashReporter(2852:2885): --- Backtrace for thread #0 (TID 55) ---
2302.744 CrashReporter(2852:2885): 0x00000002ced42017: [/usr/lib/libsystem.so] syscall1 +0x7 (syscall.cpp:20 => syscall.cpp:19)
2302.839 CrashReporter(2852:2885): 0x0000001f03a36891: [/usr/local/bin/dash] waitproc +0x4a ()
2302.851 CrashReporter(2852:2885): 0x0000001f03a36655: [/usr/local/bin/dash] dowait +0x3c ()
2302.851 CrashReporter(2852:2885): 0x0000001f03a365a0: [/usr/local/bin/dash] waitforjob +0x57 ()
2302.996 CrashReporter(2852:2885): 0x0000001f03a2f9a6: [/usr/local/bin/dash] evalcommand +0x681 ()
.....

[oskar-skog]

Something interesting just happened.

I was trying to run make on riscv64 but forgot to set the time, so I interrupted it.
It must have been during an exec syscall; it was 'make' when it got the signal, but 'dash' when it got coredumped.

1782.870 [#0 make(2537:2537)]: copy_to_user(0x00000012b34af9c8, 0x00000020185e93c8, 8) failed at V0x00000012b34af9c8
1782.870 [#0 make(2537:2537)]: Invalid stack pointer: 80317446608
1782.870 [#0 make(2537:2537)]: Terminating make(2537) due to signal 2
1783.187 [#0 Finalizer Task(6:6)]: Backtrace:
0x000000200048b7de  Kernel::ProcessorBase::switch_context(Kernel::Thread*&, Kernel::Thread*&) + 0x102
0x0000002000448a7c  Kernel::Scheduler::context_switch(Kernel::Thread*) + 0x126
0x000000200044a29a  Kernel::Scheduler::pick_next() + 0x104
0x00000020004912f6  restore_context_and_sret + 0x0
0xdeadc0de
1783.211 [#0 Finalizer Task(6:6)]: Generating coredump for pid: 2537
1785.236 CrashDaemon(35): New coredump file: /tmp/coredump/dash_2537_1784
1785.244 CrashDaemon(35): Unable to map coredump /tmp/coredump/dash_2537_1784: open: Permission denied (errno=13)
1785.266 [#0 make(2534:2534)]: Terminating make(2534) due to signal 2
1785.346 [#0 dash(2503:2503)]: Terminating dash(2503) due to signal 2
1936.967 CrashReporter(2545:2546): Generating backtrace took 5 ms
1937.643 CrashReporter(2545:2546): --- Backtrace for thread #0 (TID 2537) ---
1937.643 CrashReporter(2545:2546): 0x0000000000000000: ???

In CrashReporter I can see that all registers are zero and that the only memory regions are /usr/lib/Loader.so, the signal trampoline, and the stack for the main thread.

[implicitfield]

That's interesting. It seems like the execve syscall's locking isn't really sound. Here we're resetting various signal related things:

serenity/Kernel/Syscalls/execve.cpp

Lines 570 to 573 in 4429f0c

	auto* current_thread = Thread::current();
	current_thread->reset_signals_for_exec();
	clear_signal_handlers_for_exec();

But at this point the scheduler lock isn't held, interrupts are enabled, and we aren't in a critical section. If something (e.g. an IRQ or an exception) causes signals to be dispatched between this point and this reaching the critical section, then any signals with non-default signal actions (except notably those with SIG_IGN) won't be handled as intended.

[oskar-skog]

I managed to get a segfault on x86_64 when testing #26493. I think it may be as simple a well timed SIGINT that caused it.

0x1327dd5000 is again the beginning of the signal trampoline.

50.526 [#0 dash(73:73)]: Terminating dash(73) due to signal 2
50.532 [#0 dash(74:74)]: PV(error) fault in Region(0x000000201d3b3140)[254] at V0x00000012eff42968
50.570 [#0 dash(74:74)]: Unrecoverable page fault, write to address V0x00000012eff42968
50.601 [dash(74:74)]: CRASH: CPU #0 Page Fault in userspace
50.637 [#0 dash(74:74)]: Exception code: 0007 (isr: 0000)
50.637 [#0 dash(74:74)]:     pc=0x0023:0x0000001327dd5000 rflags=0x0000000000010202
50.643 [#0 dash(74:74)]:  stack=0x00000012eff42480  fs=0x0000000000592000  gs=0x000000201cb0b018
50.652 [#0 dash(74:74)]:    rax=0x0000000000000000 rbx=0x0000000000000064 rcx=0x00000017d6988004 rdx=0x0000000000000000
50.663 [#0 dash(74:74)]:    rbp=0x00000012eff42980 rsp=0x000000201168ff10 rsi=0x00000010a8b200f0 rdi=0x00000011d393bd78
50.676 [#0 dash(74:74)]:     r8=0x0000001f9f940270  r9=0x00000011d393c0a2 r10=0x0000000000000020 r11=0x0000000000000246
50.685 [#0 dash(74:74)]:    r12=0x0000000000000000 r13=0x00000012eff432b8 r14=0x0000000000000000 r15=0x0000000000000003
50.714 [#0 dash(74:74)]:    cr0=0x0000000080010013 cr2=0x0000002011910000 cr3=0x00000000143a9000 cr4=0x0000000000340ee0
50.718 [#0 dash(74:74)]: 0x0000001327dd5000  (?)

50.718 [#0 dash(74:74)]: Kernel backtrace:
Kernel + 0x00000000004ab161  Kernel::Process::crash(int, AK::Optional<Kernel::RegisterState const&>, bool) +0x1c1
Kernel + 0x0000000000489a32  Kernel::handle_crash(Kernel::RegisterState const&, char const*, int, bool) +0x642
Kernel + 0x0000000000007b79  Kernel::PageFault::handle(Kernel::RegisterState&) +0x8f9
Kernel + 0x0000000000516991  page_fault_handler +0xc1
Kernel + 0x0000000000514a4e  page_fault_asm_entry +0x2e
50.845 [#0 Finalizer Task(8:8)]: Generating coredump for pid: 74
51.037 CrashDaemon(37): New coredump file: /tmp/coredump/dash_74_1766435343
54.405 CrashReporter(76:77): Generating backtrace took 1699 ms
54.454 CrashReporter(76:77): --- Backtrace for thread #0 (TID 74) ---
54.462 CrashReporter(76:77): 0x0000001327dd5000: ???
54.462 CrashReporter(76:77): 0x000000074baea4df: [/usr/local/bin/dash] forkshell +0x17 ()
54.485 CrashReporter(76:77): 0x000000074bae3004: [/usr/local/bin/dash] evalpipe +0xf5 ()
54.493 CrashReporter(76:77): 0x000000074bae2820: [/usr/local/bin/dash] evaltree +0x296 ()
54.493 CrashReporter(76:77): 0x000000074bae3cbe: [/usr/local/bin/dash] evalfun +0x170 ()
54.509 CrashReporter(76:77): 0x000000074bae3990: [/usr/local/bin/dash] evalcommand +0x66b ()
54.517 CrashReporter(76:77): 0x000000074bae2820: [/usr/local/bin/dash] evaltree +0x296 ()
54.517 CrashReporter(76:77): 0x000000074bae28ee: [/usr/local/bin/dash] evaltreenr +0x1f ()
54.517 CrashReporter(76:77): 0x000000074bae322c: [/usr/local/bin/dash] evalbackcmd +0xfc ()
54.540 CrashReporter(76:77): 0x000000074bae61bf: [/usr/local/bin/dash] expbackq +0xa6 ()
54.551 CrashReporter(76:77): 0x000000074bae5cab: [/usr/local/bin/dash] argstr +0x2f8 ()
54.551 CrashReporter(76:77): 0x000000074bae5882: [/usr/local/bin/dash] expandarg +0x47 ()
54.551 CrashReporter(76:77): 0x000000074bae35c1: [/usr/local/bin/dash] evalcommand +0x29c ()
54.585 CrashReporter(76:77): 0x000000074bae2820: [/usr/local/bin/dash] evaltree +0x296 ()
54.585 CrashReporter(76:77): 0x000000074baeb904: [/usr/local/bin/dash] cmdloop +0x11c ()
54.585 CrashReporter(76:77): 0x000000074baeb7e2: [/usr/local/bin/dash] main +0x24a ()
54.585 CrashReporter(76:77): 0x000000074bae02e4: [/usr/local/bin/dash] _entry +0x24 (crt0.cpp:47)