Bug 910649 - kernel BUG at arch/x86/kernel/kprobes.c:356
Summary: kernel BUG at arch/x86/kernel/kprobes.c:356
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 19
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-02-13 06:17 UTC by Frank Ch. Eigler
Modified: 2013-10-09 14:07 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-10-09 14:07:31 UTC
Type: Bug


Attachments (Terms of Use)
Have ftrace notifier run at the end of module unloading (2.39 KB, patch)
2013-02-13 20:09 UTC, Steven Rostedt
no flags Details | Diff

Description Frank Ch. Eigler 2013-02-13 06:17:18 UTC
Seen during systemtap testsuite, on current rawhide kernel

# yum install systemtap-testsuite kernel-debuginfo [etc]
# rpm -qa kernel\* systemtap\*
kernel-3.8.0-0.rc7.git0.1.fc19.x86_64
kernel-debuginfo-3.8.0-0.rc7.git0.1.fc19.x86_64
kernel-debuginfo-common-x86_64-3.8.0-0.rc7.git0.1.fc19.x86_64
kernel-devel-3.8.0-0.rc7.git0.1.fc19.x86_64
kernel-headers-3.8.0-0.rc7.git0.1.fc19.x86_64
systemtap-2.1-0.385.gab733d5.fc19.x86_64
systemtap-client-2.1-0.385.gab733d5.fc19.x86_64
systemtap-devel-2.1-0.385.gab733d5.fc19.x86_64
systemtap-runtime-2.1-0.385.gab733d5.fc19.x86_64
systemtap-sdt-devel-2.1-0.385.gab733d5.fc19.x86_64
systemtap-server-2.1-0.385.gab733d5.fc19.x86_64
systemtap-testsuite-2.1-0.385.gab733d5.fc19.x86_64
# cd /usr/share/systemtap/testsuite
# make installcheck RUNTESTFLAGS="pr10854.exp pr13158.exp"

observe:

[  100.363931] stap_1efffcf7195606a7cb1f349c6a83387b_845207: systemtap: 2.1/0.155, base: ffffffffa0196000, memory: 4240data/52text/31ctx/2058net/401alloc kb, probes: 6012
[  134.553683] ------------[ cut here ]------------
[  134.554034] kernel BUG at arch/x86/kernel/kprobes.c:356!
[  134.554034] invalid opcode: 0000 [#1] SMP 
[  134.554034] Modules linked in: stap_1efffcf7195606a7cb1f349c6a83387b_845207(F) nfsv4 auth_rpcgss nfs dns_resolver fscache lockd sunrpc ppdev parport_pc virtio_net microcode i2c_piix4 parport drm_kms_helper ttm drm i2c_core [last unloaded: stap_0d8cb8895a16e93afcdd24a8456989c5_869]
[  134.554034] CPU 0 
[  134.554034] Pid: 2028, comm: stapio Tainted: GF            3.8.0-0.rc7.git0.1.fc19.x86_64 #1 Bochs Bochs
[  134.554034] RIP: 0010:[<ffffffff8163825f>]  [<ffffffff8163825f>] __copy_instruction+0xff/0x110
[  134.554034] RSP: 0018:ffff880078fc3d20  EFLAGS: 00010286
[  134.554034] RAX: 000000006a53107c RBX: ffffffff6a53107c RCX: 0000000000000006
[  134.554034] RDX: 00000000890000ed RSI: 0000000000000001 RDI: 0000000000000000
[  134.554034] RBP: ffff880078fc3da8 R08: fffe058bccd80000 R09: ffff880078fc3d20
[  134.554034] R10: 0000000000000000 R11: ffffffff8162f336 R12: ffffffffa00fe3a7
[  134.554034] R13: ffffffffa00fe3a7 R14: ffffffffa00fe3a7 R15: ffff880048403cc0
[  134.554034] FS:  00007f6e7adc4740(0000) GS:ffff88007cc00000(0000) knlGS:0000000000000000
[  134.554034] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  134.554034] CR2: 00007ff9d7868000 CR3: 0000000036435000 CR4: 00000000000006f0
[  134.554034] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  134.554034] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[  134.554034] Process stapio (pid: 2028, threadinfo ffff880078fc2000, task ffff88003614dd80)
[  134.554034] Stack:
[  134.554034]  0000000100000000 0000000100000000 0000000100000000 0000010100000000
[  134.554034]  0000010100000035 0000000100000000 00000401890000ed 0000000000000000
[  134.554034]  0000000000000000 0100080400004000 ffffffffa00fe3a7 ffffffffa00fe3ad
[  134.554034] Call Trace:
[  134.554034]  [<ffffffff8162f336>] ? vfs_path_lookup.part.35+0xb/0xb
[  134.554034]  [<ffffffff81639313>] arch_prepare_optimized_kprobe+0xa3/0x1e0
[  134.554034]  [<ffffffff8163abd7>] alloc_aggr_kprobe.isra.19+0x57/0x80
[  134.554034]  [<ffffffff8163c063>] register_kprobe+0x1f3/0x590
[  134.554034]  [<ffffffff8163c4cb>] ? register_kretprobe+0xcb/0x280
[  134.554034]  [<ffffffff8162f336>] ? vfs_path_lookup.part.35+0xb/0xb
[  134.554034]  [<ffffffff8163c592>] register_kretprobe+0x192/0x280
[  134.554034]  [<ffffffffa01a0801>] _stp_ctl_write_cmd+0x571/0x15b0 [stap_1efffcf7195606a7cb1f349c6a83387b_845207]
[  134.554034]  [<ffffffff811977ff>] vfs_write+0x9f/0x170
[  134.554034]  [<ffffffff811979b9>] sys_write+0x49/0xa0
[  134.554034]  [<ffffffff810dc056>] ? __audit_syscall_exit+0x1f6/0x2a0
[  134.554034]  [<ffffffff8163e419>] system_call_fastpath+0x16/0x1b
[  134.554034] Code: 85 01 d0 0f b6 55 8d 01 d0 0f b6 55 95 01 d0 0f b6 55 9d 01 d0 0f b6 55 a5 01 d0 48 98 41 89 1c 04 e9 7a ff ff ff e8 91 3d a2 ff <0f> 0b 66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 
[  134.554034] RIP  [<ffffffff8163825f>] __copy_instruction+0xff/0x110
[  134.554034]  RSP <ffff880078fc3d20>
[  134.675153] ---[ end trace ae6bb993bdcbaab4 ]---

# cat /proc/sys/debug/kprobes-optimization
[hangs]

This sounds a little like bug #809607, except this occurs for both values (0 / 1) that may be plopped into /proc/sys/debug/kprobes-optimization ahead of time.

It could be just a special case of bug #655904, except that this kernel bug is hitting earlier than usual (for a much smaller set of wildcards, one that has been stable on previous fedora & rhel kernels).

Comment 1 Frank Ch. Eigler 2013-02-13 06:34:37 UTC
Possibly related, bug #865184, except that the -rc7 kernel has srostedt's fix.  Yet this occurs during the bz6850.exp test case on the same box:

[  461.128173] ------------[ cut here ]------------
[  461.130972] WARNING: at kernel/kprobes.c:965 disarm_kprobe+0xb7/0x100()
[  461.133264] Hardware name: Bochs
[  461.135102] Failed to disarm kprobe-ftrace at ffffffffa015a3e0 (-22)
[  461.137994] Modules linked in: vfat(-) fat stap_d08e7d9c67677b1b045f0e166ad31f4c__9647(F) stap_fc1ce3eee0b2e97add2d9b267eabc16a_16193(F) nfsv4 auth_rpcgss nfs dns_resolver fscache lockd sunrpc ppdev microcode i2c_piix4 virtio_net parport_pc parport drm_kms_helper ttm drm i2c_core [last unloaded: bid_shared]
[  461.151536] Pid: 9661, comm: rmmod Tainted: GF       W    3.8.0-0.rc7.git0.1.fc19.x86_64 #1
[  461.156605] Call Trace:
[  461.157780]  [<ffffffff8105c210>] warn_slowpath_common+0x70/0xa0
[  461.159958]  [<ffffffff8105c28c>] warn_slowpath_fmt+0x4c/0x50
[  461.161975]  [<ffffffffa015a3e0>] ? vfat_find+0x60/0x60 [vfat]
[  461.164173]  [<ffffffff8163b777>] disarm_kprobe+0xb7/0x100
[  461.166217]  [<ffffffff8163b840>] __disable_kprobe+0x80/0xa0
[  461.168232]  [<ffffffff8107c830>] ? ftrace_raw_output_rcu_utilization+0xc0/0xc0
[  461.171029]  [<ffffffff8163b878>] __unregister_kprobe_top+0x18/0x1e0
[  461.173258]  [<ffffffff8163ba81>] unregister_kprobes.part.23+0x41/0xb0
[  461.175490]  [<ffffffff8163bb2f>] unregister_kprobe+0x1f/0x30
[  461.177530]  [<ffffffffa01cf0a5>] _stp_module_notifier+0x1e5/0x390 [stap_d08e7d9c67677b1b045f0e166ad31f4c__9647]
[  461.181064]  [<ffffffff81639fcc>] notifier_call_chain+0x4c/0x70
[  461.183196]  [<ffffffff81085ced>] __blocking_notifier_call_chain+0x4d/0x70
[  461.187093]  [<ffffffff81085d26>] blocking_notifier_call_chain+0x16/0x20
[  461.189377]  [<ffffffff810c05e1>] sys_delete_module+0x181/0x2d0
[  461.191456]  [<ffffffff810139e1>] ? do_notify_resume+0x61/0xa0
[  461.193521]  [<ffffffff8163e419>] system_call_fastpath+0x16/0x1b
[  461.195581] ---[ end trace aa65dfd7d023a8a0 ]---

Comment 2 Steven Rostedt 2013-02-13 20:09:37 UTC
Created attachment 697014 [details]
Have ftrace notifier run at the end of module unloading

This is the opposite bug of bug #865184. That bug was about kprobes being registered before ftrace was able to do its magic. This bug is about kprobes being removed after ftrace removed itself from modules.

Basically, ftrace needs to do clean up on module removal, as it needs to know about code being removed so that it doesn't try to modify that code. But after it removes the module from its records, if a ftrace user tries to remove a probe, that removal will fail due as the record of that code segment no longer exists.

The attached patch breaks the ftrace notifier up into two notifiers. One to run with high priority on module load, and the other to run at lowest priority on module removal. This will let other notifiers run (and release their probes) before ftrace does its final clean up.

I'll run this through my tests and push it to mainline. It wont make 3.8 but I can add a stable tag to it and make sure it gets into 3.9.

Comment 3 Josh Boyer 2013-02-14 15:16:39 UTC
(In reply to comment #2)
> I'll run this through my tests and push it to mainline. It wont make 3.8 but
> I can add a stable tag to it and make sure it gets into 3.9.

We can carry it in Fedora in the meantime.

Frank, could you test it out quickly before I pull it in?

Comment 4 Frank Ch. Eigler 2013-02-14 16:35:06 UTC
Josh/Steve, thanks, testing in progress, should take 2-3 hours.

Comment 5 Frank Ch. Eigler 2013-02-14 21:15:46 UTC
Initial results show that the opposite-of-bug#865184 case appears to be fixed, but the first reported crash (#c0 above) is still there.

Comment 6 Frank Ch. Eigler 2013-03-12 01:33:21 UTC
Still present in 3.9-rc1:

[29263.883353] stap_b14c360a8da4c4b0c8e752f48cf3b3b5_2_5271: systemtap: 2.2/0.155, base: ffffffffa0410000, memory: 293data/76text/36ctx/2058net/2289alloc kb, probes: 794
[29269.787893] ------------[ cut here ]------------
[29269.788029] kernel BUG at arch/x86/kernel/kprobes/core.c:356!
[29269.788029] invalid opcode: 0000 [#1] SMP 
[29269.788029] Modules linked in: stap_b14c360a8da4c4b0c8e752f48cf3b3b5_2_5271(F) stap_7c7fbd21ee2bfb2587fcb596c1954945_16193(F) nfsv4 auth_rpcgss nfs dns_resolver fscache lockd sunrpc ppdev parport_pc parport i2c_piix4 virtio_net microcode drm_kms_helper ttm drm i2c_core [last unloaded: stap_85ebd8563d76438f4de6bff27591ff6a_5076]
[29269.788029] CPU 1 
[29269.788029] Pid: 5271, comm: stapio Tainted: GF          O 3.9.0-0.rc1.git0.4.fc19.x86_64 #1 Bochs Bochs
[29269.788029] RIP: 0010:[<ffffffff8164804f>]  [<ffffffff8164804f>] __copy_instruction+0xff/0x110
[29269.788029] RSP: 0018:ffff880075a71d40  EFLAGS: 00010286
[29269.788029] RAX: 000000006a5ff401 RBX: ffffffff6a5ff401 RCX: 0000000000000006
[29269.788029] RDX: 0000000089485500 RSI: 0000000000000001 RDI: 0000000000000029
[29269.788029] RBP: ffff880075a71dc8 R08: af90000000000000 R09: ffff880075a71d40
[29269.788029] R10: 0000000000000000 R11: ffffffff8127b5f0 R12: ffffffffa01016f1
[29269.788029] R13: ffffffffa01016ef R14: ffffffffa01016f1 R15: 0000000000000002
[29269.788029] FS:  00002aaaaaacb680(0000) GS:ffff88007cd00000(0000) knlGS:0000000000000000
[29269.788029] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[29269.788029] CR2: 00007f6efce84000 CR3: 0000000036292000 CR4: 00000000000006e0
[29269.788029] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[29269.788029] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[29269.788029] Process stapio (pid: 5271, threadinfo ffff880075a70000, task ffff8800363eddc0)
[29269.788029] Stack:
[29269.788029]  0000000100000000 0000000100000000 0000000100000000 0000010100000029
[29269.788029]  000001010000003d 0000000100000000 0000040189485500 0000000000000000
[29269.788029]  0000000000000000 0100080400004000 ffffffffa01016f1 ffffffffa01016f7
[29269.788029] Call Trace:
[29269.788029]  [<ffffffff8107d118>] ? search_exception_tables+0x38/0x40
[29269.788029]  [<ffffffff8127b5f0>] ? compat_sys_shmctl+0x620/0x620
[29269.788029]  [<ffffffff81648fd3>] arch_prepare_optimized_kprobe+0xa3/0x1e0
[29269.788029]  [<ffffffff8164ab67>] alloc_aggr_kprobe.isra.18+0x57/0x80
[29269.788029]  [<ffffffff8164bf33>] register_kprobe+0x1f3/0x590
[29269.788029]  [<ffffffff8164c39b>] ? register_kretprobe+0xcb/0x280
[29269.788029]  [<ffffffff8127b5f0>] ? compat_sys_shmctl+0x620/0x620
[29269.788029]  [<ffffffff8164c462>] register_kretprobe+0x192/0x280
[29269.788029]  [<ffffffffa0421aa7>] _stp_ctl_write_cmd+0x587/0xae0 [stap_b14c360a8da4c4b0c8e752f48cf3b3b5_2_5271]
[29269.788029]  [<ffffffff8119922f>] vfs_write+0x9f/0x170
[29269.788029]  [<ffffffff811993e9>] sys_write+0x49/0xa0
[29269.788029]  [<ffffffff8164e639>] ? stub_clone+0x69/0x90
[29269.788029]  [<ffffffff8164e2d9>] system_call_fastpath+0x16/0x1b
[29269.788029] Code: 85 01 d0 0f b6 55 8d 01 d0 0f b6 55 95 01 d0 0f b6 55 9d 01 d0 0f b6 55 a5 01 d0 48 98 41 89 1c 04 e9 7a ff ff ff e8 31 47 a1 ff <0f> 0b 66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 
[29269.788029] RIP  [<ffffffff8164804f>] __copy_instruction+0xff/0x110
[29269.788029]  RSP <ffff880075a71d40>
[29269.899274] ---[ end trace fda8cebfcdb226f9 ]---

Comment 7 Masami Hiramatsu 2013-03-12 01:53:12 UTC
I think this code should not use BUG_ON(). It should check sanity, print more productive error message, and return an error. Or we just can't find what happen on that!

Comment 8 Fedora End Of Life 2013-04-03 15:44:28 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 19 development cycle.
Changing version to '19'.

(As we did not run this process for some time, it could affect also pre-Fedora 19 development
cycle bugs. We are very sorry. It will help us with cleanup during Fedora 19 End Of Life. Thank you.)

More information and reason for this action is here:
https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora19

Comment 9 Frank Ch. Eigler 2013-05-17 11:38:23 UTC
Last encountered yesterday in 3.9.2-301.fc19.x86_64 #1 Bochs Bochs

Comment 10 Frank Ch. Eigler 2013-06-04 20:23:19 UTC
It appears that low-kernel-memory conditions make this BUG more likely,
such as systemtap's errsnoop.* sample.  (That one allocated a few hundred
megabytes of kernel RAM, just for the fun that's in it.  We'll fix that soon,
so get it while it can still help trigger the BUG.)  NB: The bug seems to trigger
regardless of the kprobes-optimization setting, which stap again disables due to
http://sourceware.org/ml/systemtap/2013-q2/msg00142.html.

Comment 11 Jonathan Lebon 2013-06-07 21:03:54 UTC
Using Masami Hiramatsu's latest patch (http://sourceware.org/ml/systemtap/2013-q2/msg00241.html), I stress-tested a VM all night yesterday with no encounter of this bug.

Comment 12 Josh Boyer 2013-09-18 20:53:36 UTC
*********** MASS BUG UPDATE **************

We apologize for the inconvenience.  There is a large number of bugs to go through and several of them have gone stale.  Due to this, we are doing a mass bug update across all of the Fedora 19 kernel bugs.

Fedora 19 has now been rebased to 3.11.1-200.fc19.  Please test this kernel update and let us know if you issue has been resolved or if it is still present with the newer kernel.

If you experience different issues, please open a new bug report for those.

Comment 13 Josh Boyer 2013-10-08 17:58:59 UTC
(In reply to Jonathan Lebon from comment #11)
> Using Masami Hiramatsu's latest patch
> (http://sourceware.org/ml/systemtap/2013-q2/msg00241.html), I stress-tested
> a VM all night yesterday with no encounter of this bug.

Is this issue resolved with that then?

Comment 14 Jonathan Lebon 2013-10-09 13:48:42 UTC
(In reply to Josh Boyer from comment #13)
> (In reply to Jonathan Lebon from comment #11)
> > Using Masami Hiramatsu's latest patch
> > (http://sourceware.org/ml/systemtap/2013-q2/msg00241.html), I stress-tested
> > a VM all night yesterday with no encounter of this bug.
> 
> Is this issue resolved with that then?

Hi Josh,

To make sure, I stress-tested this again on 3.11.3-201.fc19.x86_64 using the older version of the errsnoop sample (which was modified to be nicer, as mentioned in comment #10) and ran into no problems. So I believe it is resolved.

Comment 15 Josh Boyer 2013-10-09 14:07:31 UTC
Great, thanks.


Note You need to log in before you can comment on or make changes to this bug.