This message generated a parse failure. Raw output follows here. Please use 'back' to navigate. From devnull@lkml.org Sun May 5 02:21:41 2024 Envelope-to: j@jasper.es Delivery-date: Tue, 04 Feb 2014 18:33:30 +0100 Received: from localhost ([127.0.0.1] helo=squeeze.vs19.net) by squeeze.vs19.net with esmtp (Exim 4.80) (envelope-from ) id 1WAjUQ-0003GU-QO for j@jasper.es; Tue, 04 Feb 2014 18:08:50 +0100 Original-Recipient: rfc822;jasper@telfort.nl Received: from pop3.telfort.nl [213.75.3.52] by squeeze.vs19.net with POP3 (fetchmail-6.3.21) for (single-drop); Tue, 04 Feb 2014 18:08:50 +0100 (CET) Received: from cpxmta-msg03.kpnxchange.com (10.94.114.24) by cpxmbs-msg01.support.local (8.6.060.31) id 52B0AB3D022CED36 for jasper@telfort.nl; Tue, 4 Feb 2014 18:05:14 +0100 Received: from cpsmtpb-ews02.kpnxchange.com (213.75.39.5) by cpxmta-msg03.kpnxchange.com (8.6.060.14) id 527999DA0A6A35E9 for jasper@telfort.nl; Tue, 4 Feb 2014 18:05:14 +0100 Received: from cpsps-ews28.kpnxchange.com ([10.94.84.194]) by cpsmtpb-ews02.kpnxchange.com with Microsoft SMTPSVC(7.5.7601.17514); Tue, 4 Feb 2014 18:05:14 +0100 Received: from vger.kernel.org ([209.132.180.67]) by cpsps-ews28.kpnxchange.com with Microsoft SMTPSVC(7.5.7601.17514); Tue, 4 Feb 2014 18:05:14 +0100 Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754843AbaBDRFJ convert rfc822-to-quoted-printable (ORCPT ); Tue, 4 Feb 2014 12:05:09 -0500 Received: from cdptpa-outbound-snat.email.rr.com ([107.14.166.225]:40501 "EHLO cdptpa-oedge-vip.email.rr.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1754010AbaBDRFF convert rfc822-to-8bit (ORCPT ); Tue, 4 Received: from [67.255.60.225] ([67.255.60.225:52360] helo=gandalf.local.home) by cdptpa-oedge03 (envelope-from ) (ecelerity 3.5.0.35861 r(Momo-dev:tip)) with ESMTP id F6/4C-05632-DBD11F25; Tue, 04 Feb 2014 17:05:04 +0000 Date: Tue, 4 Feb 2014 12:05:00 -0500 From: Steven Rostedt To: LKML Cc: Linus Torvalds , Andrew Morton , Oleg Nesterov , Al Viro , David Smith , Peter Zijlstra , Igor Zhbanov X-Mailer: Claws Mail 3.9.3 (GTK+ 2.24.22; x86_64-pc-linux-gnu) Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: QUOTED-PRINTABLE X-RR-Connecting-IP: 107.14.168.142:25 X-Cloudmark-Score: 0 Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-Id: X-Mailing-List: linux-kernel@vger.kernel.org X-OriginalArrivalTime: 04 Feb 2014 17:05:14.0287 (UTC) FILETIME=[455D8BF0:01CF21CB] X-RcptDomain: telfort.nl Igor reported garbage in a trace that looked like this: login-1718 [000] ...1 1340.195118: sched_process_exec: fil= ename=3D/bin/login pid=3D1718 old_pid=3D1718 systemd-cgroups-2061 [006] ...1 1341.672207: sched_process_exec: fil= ename=3D/usr/lib/systemd/systemd-cgroups-agent pid=3D2061 old_pid=3D206= 1 systemd-cgroups-2063 [004] ...1 1341.673437: sched_process_exec: fil= ename=3D=C3=80=C3=88=C3=BB=C3=89 pid=3D2063 old_pid=3D2063 See the junk in the last line for filename. Investigating this, I found that the problem is where the tracepoint lies. In exec.c exec_binprm() we have: ret =3D search_binary_handler(bprm); if (ret >=3D 0) { audit_bprm(bprm); trace_sched_process_exec(current, old_pid, bprm); The tracepoint uses bprm->filename to record the process that was executed. The problem is that the handlers called in search_binary_handler() can release the process' old memory for the new memory. The bprm->filename is not in this memory, but the issue is when this happens, if the parent used a vfork() it will wake up at that moment. To explain exactly what happens, we have this: cgroup_release_agent() agentbuf =3D kstrdup(); argv[0] =3D argentbuf; call_usermodehelper(argv[0],...,UMH_WAIT_EXEC); call_usermodehelper_setup() sub_info->path =3D path; (argv[0] from parameter) sub_info->work =3D __call_usermodehelper; call_usermodehelper_exec() queue_work(subinfo->work); wait_for_completion(); Now the work gets called: __call_usermodehelper kernel_thread(call_helper, CLONE_VFORK); Notice the VFORK flag. This means that the parent will sleep till the child exits or execs. call_helper() ____call_usermodehelper() do_execve(subinfo->path) filename =3D subinfo->path; (filename is allocated agentbuf) do_execve_common(filename) bprm->filename =3D filename; exec_bprm(bprm) search_binary_handler(bprm) fmt->load_binary() (load_elf_binary); load_elf_binary() flush_old_exec() exec_mmap() mm_release() if (tsk->vfork_done) complete_vfork_done(tsk); Here we wake up the parent. The one that called kthread_thread(call_helper). Now that one continues to run: case UMH_WAIT_EXEC: if (pid < 0) sub_info->retval =3D pid; umh_complete(sub_info); Now this wakes up the process that's waiting for completion. Which continues to run and does: kfree(agentbuf); This is what bprm->filename points to. When the search_binary_handler() returns, (with a possibility that filename has been freed), when it calls the tracepoint, the tracepoint will record bogus data. Luckily it didn't crash the kernel. Adding a few strategic trace_printks, we can see this happening: kworker/3:1-51 [003] .... 59.700772: cgroup_release_agent: a= gentbuf =3D ffff880114fc28c0 /usr/lib/systemd/systemd-cgroups-agent systemd-cgroups-1925 [005] .... 59.700866: do_execve_common.isra.2= 5: calling search_binary_handler (bprm->filename=3Dffff880114fc28c0 /us= r/lib/systemd/systemd-cgroups-agent systemd-cgroups-1925 [005] .... 59.700867: search_binary_handler: = fmt->load_binary =3D load_misc_binary+0x0/0x302 systemd-cgroups-1925 [005] .... 59.700868: search_binary_handler: = fmt->load_binary =3D load_script+0x0/0x1e8 systemd-cgroups-1925 [005] .... 59.700868: search_binary_handler: = fmt->load_binary =3D load_elf_binary+0x0/0x179b systemd-cgroups-1925 [005] .... 59.700876: flush_old_exec: calling= exec_mmap bprm->filename=3Dffff880114fc28c0 /usr/lib/systemd/systemd-c= groups-agent systemd-cgroups-1925 [005] .... 59.700876: flush_old_exec: calling= mm_release systemd-cgroups-1925 [005] .... 59.700876: mm_release: tsk->vfork_= done =3D ffff880000091d68 kworker/3:1-51 [003] .... 59.700904: cgroup_release_agent: f= reeing agentbuf systemd-cgroups-1925 [005] .... 59.700911: do_execve_common.isra.2= 5: back from binary (bprm->filename=3Dffff880114fc28c0 @$=C3=BC=14=01=C2= =88=C3=BF=C3=BF/systemd/systemd-cgroups-agent systemd-cgroups-1925 [005] ...1 59.700912: sched_process_exec: fil= ename=3D@$=C3=BC=14=01=C2=88=C3=BF=C3=BF/systemd/systemd-cgroups-agent = pid=3D1925 old_pid=3D1925 The junk starts after "freeing agentbuf" Now to fix this we need to save the filename before calling search_binary_handler(). But we don't want to save it if we are not tracing. Why slow everyone else down? To prevent this, I added a static key branch (nop or unconditional jump) that gets enabled when the tracepoint sched_process_exec is registered, and disabled when the tracepoint is unregistered. When the tracepoint is registered, the filename will be allocated by a kstrdup and freed after the call. If filename fails to allocate, we simply fall back to brpm->tcomm (just the name, not the path). This works, but is rather ugly. Looking for any other suggestions here. Reported-by: Igor Zhbanov [ I'm assuming this is the right person. All I have is a nick "IZh" on = IRC] Signed-off-by: Steven Rostedt diff --git a/fs/exec.c b/fs/exec.c index e1529b4..9bb1b0f 100644 --- a/fs/exec.c +++ b/fs/exec.c @@ -1407,9 +1407,22 @@ int search_binary_handler(struct linux_binprm *b= prm) } EXPORT_SYMBOL(search_binary_handler); =20 +static struct static_key sched_process_exec_key =3D STATIC_KEY_INIT_FA= LSE; + +void sched_process_exec_key_reg(void) +{ + static_key_slow_inc(&sched_process_exec_key); +} + +void sched_process_exec_key_unreg(void) +{ + static_key_slow_dec(&sched_process_exec_key); +} + static int exec_binprm(struct linux_binprm *bprm) { pid_t old_pid, old_vpid; + char *filename; int ret; =20 /* Need to fetch pid before load_binary changes it */ @@ -1418,10 +1431,34 @@ static int exec_binprm(struct linux_binprm *bpr= m) old_vpid =3D task_pid_nr_ns(current, task_active_pid_ns(current->pare= nt)); rcu_read_unlock(); =20 - ret =3D search_binary_handler(bprm); + /* + * When the sched_process_exec tracepoint is activated, it + * enables the static key sched_process_exec_key to do some more + * work. The issue is that the tracepoint wants to record the + * filename of the bprm but only if search_binary_handler() returns + * without an error. The problem is that the search_binary_handler() + * may call mm_release() which can wake up the parent that did a vfor= k + * (see cgroup call_usermodehelper()) and the parent may free bprm->f= ilename. + * + * The filename must be saved before calling search_binary_handler(). + * But as this is only needed for tracing, only do this work if + * the tracepoint is enabled. + * + * The static key usage removes conditional branches as well. + */=20 + if (static_key_false(&sched_process_exec_key)) { + /* If filename fails to alloc, just use tcomm */ + filename =3D kstrdup(bprm->filename, GFP_KERNEL); + ret =3D search_binary_handler(bprm); + if (ret >=3D 0) + trace_sched_process_exec(current, old_pid, + filename ? filename : bprm->tcomm); + kfree(filename); + } else + ret =3D search_binary_handler(bprm); + if (ret >=3D 0) { audit_bprm(bprm); - trace_sched_process_exec(current, old_pid, bprm); ptrace_event(PTRACE_EVENT_EXEC, old_vpid); proc_exec_connector(current); } diff --git a/include/trace/events/sched.h b/include/trace/events/sched.= h index 67e1bbf..a7eaa06 100644 --- a/include/trace/events/sched.h +++ b/include/trace/events/sched.h @@ -276,30 +276,35 @@ TRACE_EVENT(sched_process_fork, __entry->child_comm, __entry->child_pid) ); =20 +extern void sched_process_exec_key_reg(void); +extern void sched_process_exec_key_unreg(void); + /* * Tracepoint for exec: */ -TRACE_EVENT(sched_process_exec, +TRACE_EVENT_FN(sched_process_exec, =20 - TP_PROTO(struct task_struct *p, pid_t old_pid, - struct linux_binprm *bprm), + TP_PROTO(struct task_struct *p, pid_t old_pid, char *filename), =20 - TP_ARGS(p, old_pid, bprm), + TP_ARGS(p, old_pid, filename), =20 TP_STRUCT__entry( - __string( filename, bprm->filename ) + __string( filename, filename ) __field( pid_t, pid ) __field( pid_t, old_pid ) ), =20 TP_fast_assign( - __assign_str(filename, bprm->filename); + __assign_str(filename, filename); __entry->pid =3D p->pid; __entry->old_pid =3D old_pid; ), =20 TP_printk("filename=3D%s pid=3D%d old_pid=3D%d", __get_str(filename), - __entry->pid, __entry->old_pid) + __entry->pid, __entry->old_pid), + + sched_process_exec_key_reg, + sched_process_exec_key_unreg ); =20 /* -- To unsubscribe from this list: send the line "unsubscribe linux-kernel"= in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/