Sven Schnelle <svens@xxxxxxxxxxxxx> writes: > Steven Rostedt <rostedt@xxxxxxxxxxx> writes: > >> On Tue, 21 Jun 2022 17:15:47 +0200 >> Alexander Gordeev <agordeev@xxxxxxxxxxxxx> wrote: >> >>> So I assume (checked actually) the return 0 below from kernel/sched/core.c: >>> wait_task_inactive() is where it bails out: >>> >>> 3303 while (task_running(rq, p)) { >>> 3304 if (match_state && unlikely(READ_ONCE(p->__state) != match_state)) >>> 3305 return 0; >>> 3306 cpu_relax(); >>> 3307 } >>> >>> Yet, the child task is always found in __TASK_TRACED state (as seen >>> in crash dumps): >>> >>> > 101447 11342 13 ce3a8100 RU 0.0 10040 4412 strace >>> 101450 101447 0 bb04b200 TR 0.0 2272 1136 kill_child >>> 108261 101447 2 d0b10100 TR 0.0 2272 532 kill_child >>> crash> task bb04b200 __state >>> PID: 101450 TASK: bb04b200 CPU: 0 COMMAND: "kill_child" >>> __state = 8, >>> >>> crash> task d0b10100 __state >>> PID: 108261 TASK: d0b10100 CPU: 2 COMMAND: "kill_child" >>> __state = 8, >> >> If you are using crash, can you enable all trace events? >> >> Then you should be able to extract the ftrace ring buffer from crash using >> the trace.so extend (https://github.com/fujitsu/crash-trace) >> >> I guess it should still work with s390. >> >> Then you can see the events that lead up to the crash. I think there's a race in ptrace_check_attach(). It first calls ptrace_freeze_task(), which checks whether JOBCTL_TRACED is set. If it is (and a few other conditions match) it will set ret = 0. Later outside of siglock and tasklist_lock it will call wait_task_inactive, assuming the target is in TASK_TRACED, but it isn't. ptrace_stop(), which runs on another CPU, does: set_special_state(TASK_TRACED); current->jobctl |= JOBCTL_TRACED; which looks ok on first sight, but in this case JOBCTL is already set, so the reading CPU will immediately move on to wait_task_inactive(), before JOBCTL_TRACED is set. I don't know whether this is a valid combination. I never looked into JOBCTL_* semantics, but i guess now is a good time to do so. I added some debugging statements, and that gives: [ 86.218488] kill_chi-300545 2d.... 79990135us : ptrace_stop: state 8 [ 86.218492] kill_chi-300545 2d.... 79990136us : signal_generate: sig=17 errno=0 code=4 comm=strace pid=300542 grp=1 res=1 [ 86.218496] kill_chi-300545 2d.... 79990136us : sched_stat_runtime: comm=kill_child pid=300545 runtime=3058 [ns] vruntime=606165713178 [ns] [ 86.218500] kill_chi-300545 2d.... 79990136us : sched_switch: prev_comm=kill_child prev_pid=300545 prev_prio=120 prev_state=t ==> next_comm=swapper/2 next_pid=0 next_prio=120 [ 86.218504] strace-300542 7..... 79990139us : sys_ptrace -> 0x50 [ 86.218508] strace-300542 7..... 79990139us : sys_write(fd: 2, buf: 2aa198f7ad0, count: 12) [ 86.218512] strace-300542 7..... 79990140us : sys_write -> 0x12 [ 86.218515] <idle>-0 6dNh.. 79990140us : sched_wakeup: comm=kill_child pid=343805 prio=120 target_cpu=006 [ 86.218519] <idle>-0 6d.... 79990140us : sched_switch: prev_comm=swapper/6 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kill_child next_pid=343805 next_prio=120 [ 86.218524] strace-300542 7..... 79990140us : sys_write(fd: 2, buf: 2aa198f7ad0, count: 19) [ 86.218527] strace-300542 7..... 79990141us : sys_write -> 0x19 [ 86.218531] kill_chi-343805 6..... 79990141us : sys_sched_yield -> 0xffffffffffffffda [ 86.218535] strace-300542 7..... 79990141us : sys_ptrace(request: 18, pid: 53efd, addr: 0, data: 0) [ 86.218539] kill_chi-343805 6d.... 79990141us : signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0 [ 86.218543] strace-300542 7d.... 79990141us : ptrace_check_attach: task_is_traced: 1, fatal signal pending: 0 [ 86.218547] strace-300542 7..... 79990141us : ptrace_check_attach: child->pid = 343805, child->__flags=0 [ 86.218551] kill_chi-343805 6d.... 79990141us : ptrace_stop: JOBCTL_TRACED already set, state=0 <------ valid combination of flags? [ 86.218554] kill_chi-343805 6d.... 79990141us : ptrace_stop: state 8 [ 86.218558] kill_chi-343805 6d.... 79990142us : signal_generate: sig=17 errno=0 code=4 comm=strace pid=300542 grp=1 res=1 [ 86.218562] kill_chi-343805 6d.... 79990142us : sched_stat_runtime: comm=kill_child pid=343805 runtime=2135 [ns] vruntime=556109013931 [ns] [ 86.218566] strace-300542 7..... 79990142us : wait_task_inactive: NO MATCH: state 0, match_state 8, pid 343805 [ 86.218570] kill_chi-343805 6d.... 79990142us : sched_switch: prev_comm=kill_child prev_pid=343805 prev_prio=120 prev_state=t ==>next_comm=swapper/6 next_pid=0 next_prio=120
diff --git a/include/linux/sched.h b/include/linux/sched.h index c46f3a63b758..c2ddc47271b8 100644 --- a/include/linux/sched.h +++ b/include/linux/sched.h @@ -154,8 +154,8 @@ struct task_group; } while (0) #else -# define debug_normal_state_change(cond) do { } while (0) -# define debug_special_state_change(cond) do { } while (0) +# define debug_normal_state_change(cond) do { trace_printk("state %d\n", cond); } while (0) +# define debug_special_state_change(cond) do { trace_printk("state %d\n", cond); } while (0) # define debug_rtlock_wait_set_state() do { } while (0) # define debug_rtlock_wait_restore_state() do { } while (0) #endif diff --git a/kernel/ptrace.c b/kernel/ptrace.c index 156a99283b11..2cb2ae8acf23 100644 --- a/kernel/ptrace.c +++ b/kernel/ptrace.c @@ -202,6 +202,7 @@ static bool ptrace_freeze_traced(struct task_struct *task) spin_lock_irq(&task->sighand->siglock); if (task_is_traced(task) && !looks_like_a_spurious_pid(task) && !__fatal_signal_pending(task)) { + trace_printk("task_is_traced: %d, fatal signal pending: %d\n", task_is_traced(task), __fatal_signal_pending(task)); task->jobctl |= JOBCTL_PTRACE_FROZEN; ret = true; } @@ -263,8 +264,10 @@ static int ptrace_check_attach(struct task_struct *child, bool ignore_state) * child->sighand can't be NULL, release_task() * does ptrace_unlink() before __exit_signal(). */ - if (ignore_state || ptrace_freeze_traced(child)) + if (ignore_state || ptrace_freeze_traced(child)) { + trace_printk("child->pid = %d, child->__flags=%d\n", child->pid, child->__state); ret = 0; + } } read_unlock(&tasklist_lock); diff --git a/kernel/sched/core.c b/kernel/sched/core.c index da0bf6fe9ecd..73bb4c7882d0 100644 --- a/kernel/sched/core.c +++ b/kernel/sched/core.c @@ -3301,8 +3301,10 @@ unsigned long wait_task_inactive(struct task_struct *p, unsigned int match_state * is actually now running somewhere else! */ while (task_running(rq, p)) { - if (match_state && unlikely(READ_ONCE(p->__state) != match_state)) + if (match_state && unlikely(READ_ONCE(p->__state) != match_state)) { + trace_printk("NO MATCH: state %d, match_state %d, pid %d\n", p->__state, match_state, p->pid); return 0; + } cpu_relax(); } diff --git a/kernel/signal.c b/kernel/signal.c index edb1dc9b00dc..0ea8e6b6a641 100644 --- a/kernel/signal.c +++ b/kernel/signal.c @@ -2232,6 +2232,8 @@ static int ptrace_stop(int exit_code, int why, unsigned long message, if (!current->ptrace || __fatal_signal_pending(current)) return exit_code; + if (current->jobctl & JOBCTL_TRACED) + trace_printk("JOBCTL_TRACED already set, state=%d\n", current->__state); set_special_state(TASK_TRACED); current->jobctl |= JOBCTL_TRACED;
I'll continue debugging tomorrow, but maybe this helps already.