register_ftrace_function() returns 0 on ftrace_bug()

[cormander]

Running kpatch on CentOS EL7, 3.10.0-123.el7.x86_64.

I'm forcing error conditions to test error handling of the module. Here is a case where register_ftrace_function() returns 0 even though ftrace_bug() is called from the kernel during it. Not sure if there is anything we can do about it in this module, but I thought I out to report it anyway.

[ 51.202423] ------------[ cut here ]------------
[ 51.202428] WARNING: at kernel/trace/ftrace.c:1663 ftrace_bug+0x25d/0x270()
[ 51.202429] Modules linked in: kpatch_tpe(OF+) tpe(OF) kpatch(OF) ip6t_rpfilter ip6t_REJECT ipt_REJECT xt_conntrack ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw iptable_filter ip_tables sg coretemp crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel lrw ppdev gf128mul glue_helper ablk_helper cryptd vmw_balloon serio_raw pcspkr parport_pc i2c_piix4 parport vmw_vmci shpchp mperf nfsd auth_rpcgss nfs_acl lockd sunrpc uinput xfs libcrc32c sr_mod cdrom sd_mod crc_t10dif crct10dif_common ata_generic pata_acpi mptspi
[ 51.202446] scsi_transport_spi ahci vmwgfx ttm mptscsih libahci e1000 mptbase drm ata_piix libata i2c_core floppy dm_mirror dm_region_hash dm_log dm_mod [last unloaded: kpatch_tpe]
[ 51.202452] CPU: 3 PID: 3041 Comm: insmod Tainted: GF U O-------------- 3.10.0-123.el7.x86_64 #1
[ 51.202453] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/31/2013
[ 51.202454] 0000000000000000 00000000c5f584bc ffff88005eb6fb08 ffffffff815e19ba
[ 51.202456] ffff88005eb6fb40 ffffffff8105dee1 ffff88007c0635e0 ffffffff812515a0
[ 51.202457] 000000000000235e ffffffff81d48110 ffffffff815f1cd0 ffff88005eb6fb50
[ 51.202458] Call Trace:
[ 51.202461] [] dump_stack+0x19/0x1b
[ 51.202463] [] warn_slowpath_common+0x61/0x80
[ 51.202465] [] ? security_bprm_set_creds+0x20/0x20
[ 51.202466] [] ? fentry+0x10/0x10
[ 51.202468] [] warn_slowpath_null+0x1a/0x20
[ 51.202469] [] ftrace_bug+0x25d/0x270
[ 51.202470] [] ftrace_replace_code+0x2b9/0x420
[ 51.202472] [] ? security_bprm_set_creds+0x20/0x20
[ 51.202473] [] ftrace_modify_all_code+0x62/0x80
[ 51.202474] [] arch_ftrace_update_code+0x10/0x20
[ 51.202476] [] ftrace_run_update_code+0x1e/0x80
[ 51.202477] [] ftrace_startup_enable+0x39/0x50
[ 51.202479] [] ftrace_startup+0xc1/0x270
[ 51.202480] [] register_ftrace_function+0x43/0x60
[ 51.202482] [] kpatch_link_object+0x2d0/0x560 [kpatch]
[ 51.202484] [] ? 0xffffffffa0502fff
[ 51.202486] [] kpatch_register+0x9b/0x4f0 [kpatch]
[ 51.202487] [] ? __kmalloc+0x1f3/0x230
[ 51.202489] [] patch_init+0x37a/0x1000 [kpatch_tpe]
[ 51.202491] [] ? 0xffffffffa050efff
[ 51.202492] [] do_one_initcall+0xe2/0x190
[ 51.202494] [] load_module+0x129b/0x1a90
[ 51.202495] [] ? ddebug_proc_write+0xf0/0xf0
[ 51.202497] [] ? copy_module_from_fd.isra.43+0x53/0x150
[ 51.202498] [] SyS_finit_module+0xa6/0xd0
[ 51.202500] [] system_call_fastpath+0x16/0x1b
[ 51.202501] ---[ end trace 7f62e2edcab0ad39 ]---
[ 51.202501] ftrace failed to modify [] security_bprm_check+0x0/0x30
[ 51.202503] actual: e9:db:71:2b:1f
[ 51.202505] Failed on adding breakpoints (9054):
[ 51.207685] kpatch: setting reg to true for 'security_bprm_check', register_ftrace_function returned 0
[ 51.208492] kpatch: can't set ftrace filter at address 0xffffffff81251d90
[ 51.208494] kpatch: can't unregister ftrace handler

Following this are two more calls to WARN for kpatch_unlink_object().

When kpatch then gets unloaded, it WARNs on kpatch_exit(), and successive attempts to load patch modules after kpatch is reloaded fail. A reboot is required to fix the problem.

Here is what I think is the relevant portion of the above stack trace:

[ 51.202428] WARNING: at kernel/trace/ftrace.c:1663 ftrace_bug+0x25d/0x270()
[ 51.202469] [] ftrace_bug+0x25d/0x270
[ 51.202470] [] ftrace_replace_code+0x2b9/0x420
[ 51.202480] [] register_ftrace_function+0x43/0x60
[ 51.202482] [] kpatch_link_object+0x2d0/0x560 [kpatch]
[ 51.202501] ftrace failed to modify [] security_bprm_check+0x0/0x30
[ 51.202505] Failed on adding breakpoints (9054):
[ 51.207685] kpatch: kpatch_ftrace_add_func finished for 'security_bprm_check', register_ftrace_function returned 0
[ 51.208492] kpatch: can't set ftrace filter at address 0xffffffff81251d90
[ 51.208494] kpatch: can't unregister ftrace handler

I added the printk to get this: "kpatch_ftrace_add_func finished for 'security_bprm_check', register_ftrace_function returned 0". So even though we ran into a failure condition, the code flow is proceeding, running into an error further down, and thus running into the additional errors for kpatch_unlink_object().

Any ideas? Perhaps the "real" fix for this is to push a patch upstream to fix register_ftrace_function() so it properly returns an error when it descends into ftrace_bug() madness? Or, in addition, is there a way to detect that this bug happened, or that the function isn't really registered, and properly divert the code flow to the error handling?

[cormander]

So the ftrace_disabled symbol gets set on a call to ftrace_bug(). We can check this in places to prevent unneeded verbose errors, and tell the user what the real issue is. The following commit is a POC for that;

4f7c587

Let me know if you have any questions.

[cormander]

The next commit f26de22 is cleaner.

[jpoimboe]

Perhaps the "real" fix for this is to push a patch upstream to fix register_ftrace_function() so it properly returns an error when it descends into ftrace_bug() madness?

Yeah, it seems to me that changing register_ftrace_function() to return an error is the "real" fix. I'll talk to Steve Rostedt (ftrace maintainer) about it.

I think you forced this error, but otherwise I think this error scenario would be very rare, right?

[cormander]

I didn't force the error intentionally. I ran into it while loading a kpatch that crossed the streams with tpe-lkm. We don't this this condition if #384 is accepted, but I thought, I can put in a safety for it, so why not?

My main deal is - while the condition might be rare, this adds a saner flow to handling the error.

[jpoimboe]

I'd much rather have ftrace handle its own errors, so we don't have to have knowledge of ftrace internals (which are subject to change at any time) in kpatch.

[cormander]

Totally understand. Kernel internals change a lot :)

Part of my commit is a check for ftrace_enabled (see #387 ) which is an exported sysctl entry that shouldn't ever change. Thoughts on still checking that? I believe it gets set to zero if ftrace_bug was called. Maybe not keep it as is - there may be a better way to check for a sysctl flag from within a kernel module.

[jpoimboe]

True, ftrace_enabled is unlikely to ever change. But it's still not exported to kernel modules, and accessing it via kallsyms is pretty hackish (but the only way I know of). What's the advantage of kpatch checking ftrace_enabled vs having ftrace properly return an error?

[cormander]

The advantage of checking ftrace_enabled is outlined in #387

Essentially, if its off, things don't work but the user would otherwise have no indication of that.

[jpoimboe]

What I'm trying to ask is, assuming register_ftrace_function() can be changed to return an error if ftrace_enabled is 0, wouldn't that be better than checking ftrace_enabled in kpatch?

[cormander]

If the upstream checks both the ftrace_ enabled/disabled flags and returns a proper error, then yes that should solve both of these problems.

[jpoimboe]

Ok. I think Steve's on vacation but I'll ask him about it when he gets back. I might work up some ftrace patches to fix these issues if I get the chance.

[jpoimboe]

To summarize, we need ftrace to return errors on the following conditions:

• !ftrace_enabled
• ftrace_disabled
• ftrace_bug
• bad first instruction

[cormander]

Looks good, thank you!