[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <1375322866.5418.46.camel@gandalf.local.home>
Date: Wed, 31 Jul 2013 22:07:46 -0400
From: Steven Rostedt <rostedt@...dmis.org>
To: Oleg Nesterov <oleg@...hat.com>
Cc: linux-kernel@...r.kernel.org,
Masami Hiramatsu <masami.hiramatsu.pt@...achi.com>,
"zhangwei(Jovi)" <jovi.zhangwei@...wei.com>,
Jiri Olsa <jolsa@...hat.com>,
Peter Zijlstra <a.p.zijlstra@...llo.nl>,
Arnaldo Carvalho de Melo <acme@...stprotocols.net>,
Srikar Dronamraju <srikar@...ux.vnet.ibm.com>,
Frederic Weisbecker <fweisbec@...il.com>,
Ingo Molnar <mingo@...hat.com>,
Andrew Morton <akpm@...ux-foundation.org>
Subject: Re: [RFC][PATCH 3/4] tracing/kprobes: Fail to unregister if probe
event files are open
On Wed, 2013-07-31 at 18:42 -0400, Steven Rostedt wrote:
>
> > This should be fine. Either event_remove() path takes event_mutex
> > first and then ->write() fails, or ftrace_event_enable_disable()
> > actually disables this even successfully.
>
> Actually I meant while in unregister_trace_probe(), it gets by the
> trace_probe_is_enabled() part first, then the write succeeds (as the
> event_mutex isn't taken till unregister_probe_event()). The the
> unregister_probe_event fails, but the tp was freed. The event files
> still reference the tp and this is where a crash can happen without this
> patch set.
And it's not just theoretical. I worked on a program to try to trigger
this bug, and succeeded :-) (I've never been so happy being able to
crash my kernel)
[ 128.999772] BUG: unable to handle kernel paging request at 00000005000000f9
[ 129.000015] IP: [<ffffffff810dee70>] probes_open+0x3b/0xa7
[ 129.000015] PGD 7808a067 PUD 0
[ 129.000015] Oops: 0000 [#1] PREEMPT SMP
[ 129.000015] Dumping ftrace buffer:
<skip>
[ 129.000015] ---------------------------------
[ 129.000015] Modules linked in: ipt_MASQUERADE sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables uinput snd_hda_codec_idt kvm_intel snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm kvm snd_page_alloc snd_timer shpchp snd microcode i2c_i801 soundcore pata_acpi firewire_ohci firewire_core crc_itu_t ata_generic i915 drm_kms_helper drm i2c_algo_bit i2c_core video
[ 129.000015] CPU: 1 PID: 2070 Comm: test-kprobe-rem Not tainted 3.11.0-rc3-test+ #47
[ 129.000015] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./To be filled by O.E.M., BIOS SDBLI944.86P 05/08/2007
[ 129.000015] task: ffff880077756440 ti: ffff880076e52000 task.ti: ffff880076e52000
[ 129.000015] RIP: 0010:[<ffffffff810dee70>] [<ffffffff810dee70>] probes_open+0x3b/0xa7
[ 129.000015] RSP: 0018:ffff880076e53c38 EFLAGS: 00010203
[ 129.000015] RAX: 0000000500000001 RBX: ffff88007844f440 RCX: 0000000000000003
[ 129.000015] RDX: 0000000000000003 RSI: 0000000000000003 RDI: ffff880076e52000
[ 129.000015] RBP: ffff880076e53c58 R08: ffff880076e53bd8 R09: 0000000000000000
[ 129.000015] R10: ffff880077756440 R11: 0000000000000006 R12: ffffffff810dee35
[ 129.000015] R13: ffff880079250418 R14: 0000000000000000 R15: ffff88007844f450
[ 129.000015] FS: 00007f87a276f700(0000) GS:ffff88007d480000(0000) knlGS:0000000000000000
[ 129.000015] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 129.000015] CR2: 00000005000000f9 CR3: 0000000077262000 CR4: 00000000000007e0
[ 129.000015] Stack:
[ 129.000015] ffff880076e53c58 ffffffff81219ea0 ffff88007844f440 ffffffff810dee35
[ 129.000015] ffff880076e53ca8 ffffffff81130f78 ffff8800772986c0 ffff8800796f93a0
[ 129.000015] ffffffff81d1b5d8 ffff880076e53e04 0000000000000000 ffff88007844f440
[ 129.000015] Call Trace:
[ 129.000015] [<ffffffff81219ea0>] ? security_file_open+0x2c/0x30
[ 129.000015] [<ffffffff810dee35>] ? unregister_trace_probe+0x4b/0x4b
[ 129.000015] [<ffffffff81130f78>] do_dentry_open+0x162/0x226
[ 129.000015] [<ffffffff81131186>] finish_open+0x46/0x54
[ 129.000015] [<ffffffff8113f30b>] do_last+0x7f6/0x996
[ 129.000015] [<ffffffff8113cc6f>] ? inode_permission+0x42/0x44
[ 129.000015] [<ffffffff8113f6dd>] path_openat+0x232/0x496
[ 129.000015] [<ffffffff8113fc30>] do_filp_open+0x3a/0x8a
[ 129.000015] [<ffffffff8114ab32>] ? __alloc_fd+0x168/0x17a
[ 129.000015] [<ffffffff81131f4e>] do_sys_open+0x70/0x102
[ 129.000015] [<ffffffff8108f06e>] ? trace_hardirqs_on_caller+0x160/0x197
[ 129.000015] [<ffffffff81131ffe>] SyS_open+0x1e/0x20
[ 129.000015] [<ffffffff81522742>] system_call_fastpath+0x16/0x1b
[ 129.000015] Code: e5 41 54 53 48 89 f3 48 83 ec 10 48 23 56 78 48 39 c2 75 6c 31 f6 48 c7 c7 d0 e6 a4 81 e8 3a 91 43 00 48 8b 05 f2 f8 96 00 eb 0c <f6> 80 f8 00 00 00 03 75 31 48 8b 00 48 3d 60 e7 a4 81 75 ec eb
[ 129.000015] RIP [<ffffffff810dee70>] probes_open+0x3b/0xa7
[ 129.000015] RSP <ffff880076e53c38>
[ 129.000015] CR2: 00000005000000f9
[ 130.555521] ---[ end trace 35f17d68fc569897 ]---
Attached is the program I used. It took lots of tweaks and doesn't
always trigger the bug on the first run. It can take several runs to
trigger. Each bug I've seen has been rather random. Twice it crashed due
to memory errors, once it just screwed up the kprobes, but the system
still ran fine. I had another kprobes error bug, when when I went to do
more tracing, it crashed.
What my program does is creates two threads (well, one thread and the
main thread). They place themselves onto CPU 0 and 1. Then the following
occurs:
CPU 0 CPU 1
----- -----
create sigprocmask probe
loop: loop:
fd = open(events/kprobes/sigprocmask/enable)
pthread_barrier_wait()
nanosleep(interval)
pthread_barrier_wait()
write(fd, "1", 1);
write(fd, "0", 1);
truncate kprobe_events
// deletes all probes
pthread_barrier_wait();
pthread_barrier_wait();
write(fd, "0", 1); // just in case
create sigprocmask probe
pthread_barrier_wait()
pthread_barrier_wait()
update interval
goto loop goto loop
I had to tweak the interval times to see where it would most likely
cause a race. When I found where it started to conflict, I placed the
range around that time and incremented it in steps related to 7/5
(~e/2). That eventually triggered the bug.
Now with this patch, I had to modify the test to give it a negative
number to place the pause before the write. That's because the switch to
removing the events slowed down the deletion and allowed the write to
always succeed (without the delay).
Anyway, I ran this in a while loop with the patch for an hour (and still
running) and it seems to keep it from crashing.
I'll update the change log to reflect this.
Thanks!
-- Steve
View attachment "test-kprobe-removal.c" of type "text/x-csrc" (3960 bytes)
Powered by blists - more mailing lists