ftrace module init race/bug

From: Alexei Starovoitov
Date: Mon Nov 07 2016 - 14:47:36 EST


Hi Steven,

I'm debugging the following spew:

[ 7139.111213] WARNING: CPU: 8 PID: 856649 at kernel/trace/ftrace.c:2747 ftrace_shutdown+0x263/0x270
[ 7139.753185] 0000000000000000 ffff881fc59eba40 ffffffff814717d1 0000000000000000
[ 7139.817019] 0000000000000000 ffff881fc59eba80 ffffffff81076e43 00000abb8179b000
[ 7139.880790] ffff881f7f3ee000 ffffffff81d1a820 0000000000000000 ffff881ff0929860
[ 7139.945423] Call Trace:
[ 7139.966365] [<ffffffff814717d1>] dump_stack+0x4d/0x6c
[ 7140.010927] [<ffffffff81076e43>] __warn+0xd3/0xf0
[ 7140.052228] [<ffffffff81076f2d>] warn_slowpath_null+0x1d/0x20
[ 7140.102523] [<ffffffff811135c3>] ftrace_shutdown+0x263/0x270
[ 7140.152065] [<ffffffff8111399e>] unregister_ftrace_function+0x1e/0x50
[ 7140.208374] [<ffffffff81108cfb>] disarm_kprobe+0xdb/0x100
[ 7140.256014] [<ffffffff81108da5>] __disable_kprobe+0x85/0x90
[ 7140.305474] [<ffffffff81108dd1>] disable_kprobe+0x21/0x40
[ 7140.352779] [<ffffffff8113264d>] disable_trace_kprobe+0xad/0xd0
[ 7140.404624] [<ffffffff8113325d>] kprobe_register+0x2d/0xf0
[ 7140.452625] [<ffffffff8112cf33>] perf_trace_event_unreg.isra.1+0x33/0x90
[ 7140.511154] [<ffffffff8112d276>] perf_trace_destroy+0x36/0x50
[ 7140.561450] [<ffffffff81145649>] tp_perf_event_destroy+0x9/0x10
[ 7140.612590] [<ffffffff8114b777>] _free_event+0xb7/0x260
[ 7140.658544] [<ffffffff8114bda4>] put_event+0x14/0x20
[ 7140.702069] [<ffffffff8114bfb8>] perf_event_release_kernel+0x208/0x280
[ 7140.759342] [<ffffffff8114c040>] perf_release+0x10/0x20
[ 7140.805201] [<ffffffff811d62c6>] __fput+0xd6/0x210
[ 7140.846497] [<ffffffff811d643e>] ____fput+0xe/0x10
[ 7140.888797] [<ffffffff81091597>] task_work_run+0x77/0x90
[ 7140.935328] [<ffffffff810799eb>] do_exit+0x2bb/0xb30
[ 7140.979603] [<ffffffff8107a2df>] do_group_exit+0x3f/0xa0
[ 7141.026167] [<ffffffff81084405>] get_signal+0x1b5/0x5d0
[ 7141.071950] [<ffffffff8101b1e8>] do_signal+0x28/0x690
[ 7141.116436] [<ffffffff81216f40>] ? ep_ptable_queue_proc+0xa0/0xa0
[ 7141.170546] [<ffffffff812175e5>] ? ep_scan_ready_list.isra.12+0x185/0x1a0
[ 7141.229848] [<ffffffff81677c25>] ? __sys_sendmsg+0x65/0x80
[ 7141.277902] [<ffffffff81072442>] exit_to_usermode_loop+0x53/0x96
[ 7141.330472] [<ffffffff8100294b>] do_syscall_64+0x8b/0xa0
[ 7141.377005] [<ffffffff8179333c>] entry_SYSCALL64_slow_path+0x25/0x25
[ 7141.432829] ---[ end trace 77eec51ed01e77ca ]---
[ 7141.473508] fuse_dev_open+0x0/0x20 [fuse] flags:2000000
[ 7141.520206] fuse_request_init+0x0/0xb0 [fuse] flags:2000000
[ 7141.569308] fuse_req_init_context+0x0/0x60 [fuse] flags:2000000
[ 7141.622772] queue_request+0x0/0x80 [fuse] flags:2000000
[ 7141.670397] fuse_retrieve_end+0x0/0x30 [fuse] flags:2000000
[ 7141.720671] fuse_dev_fasync+0x0/0x30 [fuse] flags:2000000
[ 7141.769842] fuse_dev_ioctl+0x0/0x100 [fuse] flags:2000000
[ 7141.820094] lock_request+0x0/0x50 [fuse] flags:2000000
[ 7141.870199] unlock_request+0x0/0x50 [fuse] flags:2000000
[ 7141.920406] fuse_dev_poll+0x0/0x90 [fuse] flags:2000000
[ 7141.968565] flush_bg_queue+0x0/0xd0 [fuse] flags:2000000
[ 7142.016531] queue_interrupt+0x0/0x80 [fuse] flags:2000000
...
[ 7153.127914] fuse_get_root_inode+0x0/0x4c [fuse] flags:2000000
[ 7153.179337] ------------[ cut here ]------------
[ 7153.219335] WARNING: CPU: 8 PID: 856649 at kernel/kprobes.c:959 disarm_kprobe+0xbe/0x100
[ 7153.289424] Failed to disarm kprobe-ftrace at ffffffff816f3ae0 (-19)
[ 7153.344466] Modules linked in: fuse(+) nf_log_ipv6 ip6t_REJECT nf_reject_ipv6 nf_log_ipv4 nf_log_common xt_LOG ipt_REJECT nf_reject_ipv4 xt_limit xt_multiport ip6_tunnel tunnel6 ipip ip_tunnel tunnel4 coretemp ipmi_watchdog tcp_diag inet_diag ip6table_filter xt_NFLOG nfnetlink_log xt_comment xt_statistic iptable_filter xt_mark tpm_crb mptctl mptbase i2c_piix4 dm_crypt loop ipmi_devintf acpi_cpufreq iTCO_wdt iTCO_vendor_support ipmi_si ipmi_msghandler efivars i2c_i801 i2c_core sg lpc_ich mfd_core hpilo xhci_pci xhci_hcd mpt3sas scsi_transport_sas raid_class button
[ 7153.794823] CPU: 8 PID: 856649 Comm: tcpeventd Tainted: G W 4.6.0-5_fbk1_223_gdbf0f40 #1
[ 7153.874380] Hardware name: HP ProLiant DL380 Gen9, BIOS P89 03/10/2015
[ 7153.930676] 0000000000000000 ffff881fc59eba38 ffffffff814717d1 ffff881fc59eba88
[ 7153.994469] 0000000000000000 ffff881fc59eba78 ffffffff81076e43 000003bfdb2095c0
[ 7154.058296] ffff883eecf78810 ffff883eecf78810 ffff883e945ed908 ffff883edb2095c0
[ 7154.122087] Call Trace:
[ 7154.143235] [<ffffffff814717d1>] dump_stack+0x4d/0x6c
[ 7154.188021] [<ffffffff81076e43>] __warn+0xd3/0xf0
[ 7154.229193] [<ffffffff81076eaf>] warn_slowpath_fmt+0x4f/0x60
[ 7154.278808] [<ffffffff81113048>] ? ftrace_set_filter_ip+0x68/0x80
[ 7154.332076] [<ffffffff816f3ae0>] ? tcp_send_loss_probe+0x210/0x210
[ 7154.386125] [<ffffffff81108cde>] disarm_kprobe+0xbe/0x100
[ 7154.433392] [<ffffffff81108da5>] __disable_kprobe+0x85/0x90
[ 7154.482215] [<ffffffff81108dd1>] disable_kprobe+0x21/0x40
[ 7154.528793] [<ffffffff8113264d>] disable_trace_kprobe+0xad/0xd0
[ 7154.580556] [<ffffffff8113325d>] kprobe_register+0x2d/0xf0
[ 7154.628573] [<ffffffff8112cf33>] perf_trace_event_unreg.isra.1+0x33/0x90
[ 7154.687413] [<ffffffff8112d276>] perf_trace_destroy+0x36/0x50
[ 7154.738283] [<ffffffff81145649>] tp_perf_event_destroy+0x9/0x10
[ 7154.789275] [<ffffffff8114b777>] _free_event+0xb7/0x260
[ 7154.835085] [<ffffffff8114bda4>] put_event+0x14/0x20
[ 7154.878600] [<ffffffff8114bfb8>] perf_event_release_kernel+0x208/0x280
[ 7154.935650] [<ffffffff8114c040>] perf_release+0x10/0x20
[ 7154.981433] [<ffffffff811d62c6>] __fput+0xd6/0x210
[ 7155.023478] [<ffffffff811d643e>] ____fput+0xe/0x10
[ 7155.065547] [<ffffffff81091597>] task_work_run+0x77/0x90
[ 7155.112033] [<ffffffff810799eb>] do_exit+0x2bb/0xb30
[ 7155.155608] [<ffffffff8107a2df>] do_group_exit+0x3f/0xa0
[ 7155.202120] [<ffffffff81084405>] get_signal+0x1b5/0x5d0
[ 7155.247965] [<ffffffff8101b1e8>] do_signal+0x28/0x690
[ 7155.292207] [<ffffffff81216f40>] ? ep_ptable_queue_proc+0xa0/0xa0
[ 7155.345539] [<ffffffff812175e5>] ? ep_scan_ready_list.isra.12+0x185/0x1a0
[ 7155.404848] [<ffffffff81677c25>] ? __sys_sendmsg+0x65/0x80
[ 7155.452898] [<ffffffff81072442>] exit_to_usermode_loop+0x53/0x96
[ 7155.505497] [<ffffffff8100294b>] do_syscall_64+0x8b/0xa0
[ 7155.552023] [<ffffffff8179333c>] entry_SYSCALL64_slow_path+0x25/0x25
[ 7155.609271] ---[ end trace 77eec51ed01e77cb ]---
[ 7155.671656] fuse init (API version 7.24)

ftrace is complaining that dyn_ftrace->flags is set to FTRACE_FL_DISABLED
which is expected, since 'fuse' module was just loaded
and ftrace_update_code() set it, but at the time ftrace_shutdown()
was called, the ftrace_module_enable() for 'fuse' was not called,
hence ftrace_shutdown() was complaining.

In other words the module.c is doing:
ftrace_module_init(mod); // loading 'fuse'
... // and here ftrace_shutdown() is called
err = prepare_coming_module(mod); // it didn't have a chance to clear FL_DISABLED

do you think the following diff is enough to silence the warning
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index b1870fbd2b67..edb00bf70d84 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -2744,7 +2744,7 @@ static int ftrace_shutdown(struct ftrace_ops *ops, int command)
struct dyn_ftrace *rec;

do_for_each_ftrace_rec(pg, rec) {
- if (FTRACE_WARN_ON_ONCE(rec->flags))
+ if (FTRACE_WARN_ON_ONCE(rec->flags & ~FTRACE_FL_DISABLED))
pr_warn(" %pS flags:%lx\n",
(void *)rec->ip, rec->flags);
} while_for_each_ftrace_rec();

or it's a tip of an iceberg and less hacky fix is needed?

Thanks