* fault injection caused oops in proc_flush_task
@ 2014-08-08 3:23 Dave Jones
2014-08-08 4:45 ` Eric W. Biederman
0 siblings, 1 reply; 3+ messages in thread
From: Dave Jones @ 2014-08-08 3:23 UTC (permalink / raw)
To: Linux Kernel; +Cc: Linus Torvalds, ebiederm, Al Viro
Because I don't have enough oopses in my life, I decided to play
with the fault injection code today. It's not something I hear about
people trying too often, so I wondered what horrors lurk..
So I ran this..
#!/bin/bash
for FAILTYPE in failslab fail_page_alloc
do
echo N > /sys/kernel/debug/$FAILTYPE/task-filter
echo 50 > /sys/kernel/debug/$FAILTYPE/probability
echo 500 > /sys/kernel/debug/$FAILTYPE/interval
echo -1 > /sys/kernel/debug/$FAILTYPE/times
echo 0 > /sys/kernel/debug/$FAILTYPE/space
echo 0 > /sys/kernel/debug/$FAILTYPE/verbose
echo 2 > /sys/kernel/debug/$FAILTYPE/ignore-gfp-wait
done
And then ran my usual fuzzing session, and saw this ..
Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
CPU: 2 PID: 8506 Comm: trinity-c124 Not tainted 3.16.0+ #41
task: ffff880227fc95e0 ti: ffff8800929a0000 task.ti: ffff8800929a0000
RIP: 0010:[<ffffffff8624a8f9>] [<ffffffff8624a8f9>] proc_flush_task+0x99/0x1b0
RSP: 0018:ffff8800929a3d40 EFLAGS: 00010246
RAX: 0000000000000001 RBX: ffff8800929a3d6b RCX: 0000000000000000
RDX: ffff8800929a3d6c RSI: ffff8800929a3d58 RDI: 0000000000000000
RBP: ffff8800929a3da8 R08: 000000000000000a R09: 000000000000fffb
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000001
R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000002
FS: 00007f019c95d700(0000) GS:ffff88024d100000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 00000000959e7000 CR4: 00000000001407e0
DR0: 000000000249e000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Stack:
ffff88022ad836c0 00000002929a3d58 ffff88022ad836c0 0000000132313068
ffff8800929a3d6b 373231003277b6b0 ffff88022377b600 00000000898577d0
ffff88022377b6b0 000000000000278f 0000000000000010 0000000000000000
Call Trace:
[<ffffffff8607738c>] release_task+0x4c/0x4a0
[<ffffffff86078aca>] wait_consider_task+0x70a/0xbe0
[<ffffffff860790e4>] do_wait+0x144/0x2d0
[<ffffffff8607967b>] SyS_wait4+0x7b/0x100
[<ffffffff86077110>] ? task_stopped_code+0x60/0x60
[<ffffffff8676371f>] tracesys+0xdd/0xe2
Code: d4 e0 a9 86 48 03 45 a8 89 4d a4 44 8b 78 30 48 8b 40 38 44 89 f9 4c 8b a8 40 08 00 00 31 c0 e8 6e 21 0f 00 48 8d 75 b0 89 45 b4 <49> 8b 7d 00 e8 4e 8b fa ff 48 85 c0 49 89 c6 74 18 48 89 c7 e8
RIP [<ffffffff8624a8f9>] proc_flush_task+0x99/0x1b0
Right before the oops, the last thing fault injection logged wrt that pid was..
FAULT_INJECTION: forcing a failure
CPU: 0 PID: 8506 Comm: trinity-c124 Not tainted 3.16.0+ #41
0000000000000032 00000000898577d0 ffff8800929a3b08 ffffffff86759797
ffffffff86c6a300 ffff8800929a3b28 ffffffff86358c30 0000000000008020
0000000000008020 ffff8800929a3b38 ffffffff861c6850 ffff8800929a3b88
Call Trace:
[<ffffffff86759797>] dump_stack+0x4e/0x7a
[<ffffffff86358c30>] should_fail+0x100/0x110
[<ffffffff861c6850>] should_failslab+0x40/0x50
[<ffffffff861c32de>] kmem_cache_alloc+0x5e/0x270
[<ffffffff86331e99>] ida_pre_get+0x69/0xf0
[<ffffffff86245c80>] ? proc_fill_super+0xa0/0xa0
[<ffffffff861da749>] get_anon_bdev+0x39/0x120
[<ffffffff86245c80>] ? proc_fill_super+0xa0/0xa0
[<ffffffff861da846>] set_anon_super+0x16/0x30
[<ffffffff8624605d>] proc_set_super+0x1d/0x80
[<ffffffff861db64a>] sget+0x33a/0x400
[<ffffffff86246040>] ? proc_root_lookup+0x40/0x40
[<ffffffff86245ed7>] proc_mount+0xa7/0x150
[<ffffffff861dc338>] mount_fs+0x38/0x1c0
[<ffffffff861f9574>] vfs_kern_mount+0x64/0x120
[<ffffffff861f9649>] kern_mount_data+0x19/0x30
[<ffffffff8624611c>] pid_ns_prepare_proc+0x1c/0x30
[<ffffffff86094334>] alloc_pid+0x474/0x4c0
[<ffffffff86047e10>] ? flush_tlb_mm_range+0x80/0x200
[<ffffffff8600207d>] ? copy_thread+0x11d/0x2c0
[<ffffffff86074140>] copy_process.part.29+0xab0/0x1be0
[<ffffffff8607542d>] do_fork+0xdd/0x400
[<ffffffff860a258b>] ? preempt_count_sub+0xab/0x100
[<ffffffff8634b563>] ? __this_cpu_preempt_check+0x13/0x20
[<ffffffff860757d6>] SyS_clone+0x16/0x20
[<ffffffff86763869>] stub_clone+0x69/0x90
[<ffffffff8676371f>] ? tracesys+0xdd/0xe2
Should proc_flush_task just be checking for a NULL upid->ns ?
Or is there something in the pid_ns_prepare_proc failure path
that we're failing to undo ?
thoughts?
I don't know how feasible it would be to hit that in real life
without the fault injection stuff, but an oops can't be the right
thing to do in any case.
Dave
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: fault injection caused oops in proc_flush_task
2014-08-08 3:23 fault injection caused oops in proc_flush_task Dave Jones
@ 2014-08-08 4:45 ` Eric W. Biederman
2014-08-09 14:24 ` Oleg Nesterov
0 siblings, 1 reply; 3+ messages in thread
From: Eric W. Biederman @ 2014-08-08 4:45 UTC (permalink / raw)
To: Dave Jones; +Cc: Linux Kernel, Linus Torvalds, Al Viro, Oleg Nesterov
Dave Jones <davej@redhat.com> writes:
> Because I don't have enough oopses in my life, I decided to play
> with the fault injection code today. It's not something I hear about
> people trying too often, so I wondered what horrors lurk..
>
> So I ran this..
>
> #!/bin/bash
>
> for FAILTYPE in failslab fail_page_alloc
> do
> echo N > /sys/kernel/debug/$FAILTYPE/task-filter
> echo 50 > /sys/kernel/debug/$FAILTYPE/probability
> echo 500 > /sys/kernel/debug/$FAILTYPE/interval
> echo -1 > /sys/kernel/debug/$FAILTYPE/times
> echo 0 > /sys/kernel/debug/$FAILTYPE/space
> echo 0 > /sys/kernel/debug/$FAILTYPE/verbose
> echo 2 > /sys/kernel/debug/$FAILTYPE/ignore-gfp-wait
> done
>
> And then ran my usual fuzzing session, and saw this ..
>
> Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> CPU: 2 PID: 8506 Comm: trinity-c124 Not tainted 3.16.0+ #41
> task: ffff880227fc95e0 ti: ffff8800929a0000 task.ti: ffff8800929a0000
> RIP: 0010:[<ffffffff8624a8f9>] [<ffffffff8624a8f9>] proc_flush_task+0x99/0x1b0
> RSP: 0018:ffff8800929a3d40 EFLAGS: 00010246
> RAX: 0000000000000001 RBX: ffff8800929a3d6b RCX: 0000000000000000
> RDX: ffff8800929a3d6c RSI: ffff8800929a3d58 RDI: 0000000000000000
> RBP: ffff8800929a3da8 R08: 000000000000000a R09: 000000000000fffb
> R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000001
> R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000002
> FS: 00007f019c95d700(0000) GS:ffff88024d100000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000000000000000 CR3: 00000000959e7000 CR4: 00000000001407e0
> DR0: 000000000249e000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
> Stack:
> ffff88022ad836c0 00000002929a3d58 ffff88022ad836c0 0000000132313068
> ffff8800929a3d6b 373231003277b6b0 ffff88022377b600 00000000898577d0
> ffff88022377b6b0 000000000000278f 0000000000000010 0000000000000000
> Call Trace:
> [<ffffffff8607738c>] release_task+0x4c/0x4a0
> [<ffffffff86078aca>] wait_consider_task+0x70a/0xbe0
> [<ffffffff860790e4>] do_wait+0x144/0x2d0
> [<ffffffff8607967b>] SyS_wait4+0x7b/0x100
> [<ffffffff86077110>] ? task_stopped_code+0x60/0x60
> [<ffffffff8676371f>] tracesys+0xdd/0xe2
> Code: d4 e0 a9 86 48 03 45 a8 89 4d a4 44 8b 78 30 48 8b 40 38 44 89 f9 4c 8b a8 40 08 00 00 31 c0 e8 6e 21 0f 00 48 8d 75 b0 89 45 b4 <49> 8b 7d 00 e8 4e 8b fa ff 48 85 c0 49 89 c6 74 18 48 89 c7 e8
> RIP [<ffffffff8624a8f9>] proc_flush_task+0x99/0x1b0
>
>
> Right before the oops, the last thing fault injection logged wrt that pid was..
>
> FAULT_INJECTION: forcing a failure
> CPU: 0 PID: 8506 Comm: trinity-c124 Not tainted 3.16.0+ #41
> 0000000000000032 00000000898577d0 ffff8800929a3b08 ffffffff86759797
> ffffffff86c6a300 ffff8800929a3b28 ffffffff86358c30 0000000000008020
> 0000000000008020 ffff8800929a3b38 ffffffff861c6850 ffff8800929a3b88
> Call Trace:
> [<ffffffff86759797>] dump_stack+0x4e/0x7a
> [<ffffffff86358c30>] should_fail+0x100/0x110
> [<ffffffff861c6850>] should_failslab+0x40/0x50
> [<ffffffff861c32de>] kmem_cache_alloc+0x5e/0x270
> [<ffffffff86331e99>] ida_pre_get+0x69/0xf0
> [<ffffffff86245c80>] ? proc_fill_super+0xa0/0xa0
> [<ffffffff861da749>] get_anon_bdev+0x39/0x120
> [<ffffffff86245c80>] ? proc_fill_super+0xa0/0xa0
> [<ffffffff861da846>] set_anon_super+0x16/0x30
> [<ffffffff8624605d>] proc_set_super+0x1d/0x80
> [<ffffffff861db64a>] sget+0x33a/0x400
> [<ffffffff86246040>] ? proc_root_lookup+0x40/0x40
> [<ffffffff86245ed7>] proc_mount+0xa7/0x150
> [<ffffffff861dc338>] mount_fs+0x38/0x1c0
> [<ffffffff861f9574>] vfs_kern_mount+0x64/0x120
> [<ffffffff861f9649>] kern_mount_data+0x19/0x30
> [<ffffffff8624611c>] pid_ns_prepare_proc+0x1c/0x30
> [<ffffffff86094334>] alloc_pid+0x474/0x4c0
> [<ffffffff86047e10>] ? flush_tlb_mm_range+0x80/0x200
> [<ffffffff8600207d>] ? copy_thread+0x11d/0x2c0
> [<ffffffff86074140>] copy_process.part.29+0xab0/0x1be0
> [<ffffffff8607542d>] do_fork+0xdd/0x400
> [<ffffffff860a258b>] ? preempt_count_sub+0xab/0x100
> [<ffffffff8634b563>] ? __this_cpu_preempt_check+0x13/0x20
> [<ffffffff860757d6>] SyS_clone+0x16/0x20
> [<ffffffff86763869>] stub_clone+0x69/0x90
> [<ffffffff8676371f>] ? tracesys+0xdd/0xe2
>
> Should proc_flush_task just be checking for a NULL upid->ns ?
> Or is there something in the pid_ns_prepare_proc failure path
> that we're failing to undo ?
>
> thoughts?
>
> I don't know how feasible it would be to hit that in real life
> without the fault injection stuff, but an oops can't be the right
> thing to do in any case.
Hmm.
So what we can reconstruct from your data is:
8506 probably unshared a pid namespace.
8506 called fork/clone creating the first process in a pid namespace and
alloc_pid fails.
8506 calls wait and the task it finds to be waited for is defective
and proc_flush_task oopses.
*scratches head*
So I don't think the last fault had anything to do with this failure.
My dissassembly puts the code at the call of shrink_dcache_parent but I
don't think my dissambly matches your kernel. Can you disassemble
proc_flush_task so we can at least see what is failing?
Eric
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: fault injection caused oops in proc_flush_task
2014-08-08 4:45 ` Eric W. Biederman
@ 2014-08-09 14:24 ` Oleg Nesterov
0 siblings, 0 replies; 3+ messages in thread
From: Oleg Nesterov @ 2014-08-09 14:24 UTC (permalink / raw)
To: Eric W. Biederman; +Cc: Dave Jones, Linux Kernel, Linus Torvalds, Al Viro
On 08/07, Eric W. Biederman wrote:
>
> Dave Jones <davej@redhat.com> writes:
>
> > Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> > CPU: 2 PID: 8506 Comm: trinity-c124 Not tainted 3.16.0+ #41
> > task: ffff880227fc95e0 ti: ffff8800929a0000 task.ti: ffff8800929a0000
> > RIP: 0010:[<ffffffff8624a8f9>] [<ffffffff8624a8f9>] proc_flush_task+0x99/0x1b0
> > RSP: 0018:ffff8800929a3d40 EFLAGS: 00010246
> > RAX: 0000000000000001 RBX: ffff8800929a3d6b RCX: 0000000000000000
> > RDX: ffff8800929a3d6c RSI: ffff8800929a3d58 RDI: 0000000000000000
> > RBP: ffff8800929a3da8 R08: 000000000000000a R09: 000000000000fffb
> > R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000001
> > R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000002
> > FS: 00007f019c95d700(0000) GS:ffff88024d100000(0000) knlGS:0000000000000000
> > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > CR2: 0000000000000000 CR3: 00000000959e7000 CR4: 00000000001407e0
> > DR0: 000000000249e000 DR1: 0000000000000000 DR2: 0000000000000000
> > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
> > Stack:
> > ffff88022ad836c0 00000002929a3d58 ffff88022ad836c0 0000000132313068
> > ffff8800929a3d6b 373231003277b6b0 ffff88022377b600 00000000898577d0
> > ffff88022377b6b0 000000000000278f 0000000000000010 0000000000000000
> > Call Trace:
> > [<ffffffff8607738c>] release_task+0x4c/0x4a0
> > [<ffffffff86078aca>] wait_consider_task+0x70a/0xbe0
> > [<ffffffff860790e4>] do_wait+0x144/0x2d0
> > [<ffffffff8607967b>] SyS_wait4+0x7b/0x100
> > [<ffffffff86077110>] ? task_stopped_code+0x60/0x60
> > [<ffffffff8676371f>] tracesys+0xdd/0xe2
> > Code: d4 e0 a9 86 48 03 45 a8 89 4d a4 44 8b 78 30 48 8b 40 38 44 89 f9 4c 8b a8 40 08 00 00 31 c0 e8 6e 21 0f 00 48 8d 75 b0 89 45 b4 <49> 8b 7d 00 e8 4e 8b fa ff 48 85 c0 49 89 c6 74 18 48 89 c7 e8
> > RIP [<ffffffff8624a8f9>] proc_flush_task+0x99/0x1b0
> >
> >
> > Right before the oops, the last thing fault injection logged wrt that pid was..
> >
> > FAULT_INJECTION: forcing a failure
> > CPU: 0 PID: 8506 Comm: trinity-c124 Not tainted 3.16.0+ #41
> > 0000000000000032 00000000898577d0 ffff8800929a3b08 ffffffff86759797
> > ffffffff86c6a300 ffff8800929a3b28 ffffffff86358c30 0000000000008020
> > 0000000000008020 ffff8800929a3b38 ffffffff861c6850 ffff8800929a3b88
> > Call Trace:
> > [<ffffffff86759797>] dump_stack+0x4e/0x7a
> > [<ffffffff86358c30>] should_fail+0x100/0x110
> > [<ffffffff861c6850>] should_failslab+0x40/0x50
> > [<ffffffff861c32de>] kmem_cache_alloc+0x5e/0x270
> > [<ffffffff86331e99>] ida_pre_get+0x69/0xf0
> > [<ffffffff86245c80>] ? proc_fill_super+0xa0/0xa0
> > [<ffffffff861da749>] get_anon_bdev+0x39/0x120
> > [<ffffffff86245c80>] ? proc_fill_super+0xa0/0xa0
> > [<ffffffff861da846>] set_anon_super+0x16/0x30
> > [<ffffffff8624605d>] proc_set_super+0x1d/0x80
> > [<ffffffff861db64a>] sget+0x33a/0x400
> > [<ffffffff86246040>] ? proc_root_lookup+0x40/0x40
> > [<ffffffff86245ed7>] proc_mount+0xa7/0x150
> > [<ffffffff861dc338>] mount_fs+0x38/0x1c0
> > [<ffffffff861f9574>] vfs_kern_mount+0x64/0x120
> > [<ffffffff861f9649>] kern_mount_data+0x19/0x30
> > [<ffffffff8624611c>] pid_ns_prepare_proc+0x1c/0x30
>
>
> So what we can reconstruct from your data is:
>
> 8506 probably unshared a pid namespace.
> 8506 called fork/clone creating the first process in a pid namespace and
or it simply did clone(NEWPID),
> alloc_pid fails.
> 8506 calls wait and the task it finds to be waited for is defective
> and proc_flush_task oopses.
>
> *scratches head*
Yes, strange. Looks like, ns->proc_mnt == NULL but I can't see how the
error code from get_anon_bdev() can be lost. copy_process() should fail.
> So I don't think the last fault had anything to do with this failure.
>
> My dissassembly puts the code at the call of shrink_dcache_parent
To me it looks as if d_hash_and_lookup(mnt->mnt_root) fails because
mnt == NULL, but again, I can't see how it is possible. ns->proc_mnt
is initialized by pid_ns_prepare_proc(), and kern_mount_data() simply
can't return NULL instead of IS_ERR().
> but I
> don't think my dissambly matches your kernel. Can you disassemble
> proc_flush_task so we can at least see what is failing?
Yes, my disassembly can be wrong too.
Oleg.
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2014-08-09 14:26 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2014-08-08 3:23 fault injection caused oops in proc_flush_task Dave Jones
2014-08-08 4:45 ` Eric W. Biederman
2014-08-09 14:24 ` Oleg Nesterov
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox