[Bug runtime/19833] New: monitor mode causes kernel crash when exited immediately

[Bug runtime/19833] New: monitor mode causes kernel crash when exited immediately

[flu at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=19833

            Bug ID: 19833
           Summary: monitor mode causes kernel crash when exited
                    immediately
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
          Assignee: systemtap at sourceware dot org
          Reporter: flu at redhat dot com
  Target Milestone: ---

This happens when the systemtap script exits immediately after running in 
monitor mode.

The following script causes a kernel crash:

$ while true; do stap --monitor -vve 'probe begin {println(1) exit()}'; done
Pass 5: starting run.
Running /opt/codebase/install/bin/staprun -v -v -R -M 1
/tmp/stapUpAWLw/stap_a78da046516a4f51cdefd2425658fc23_7467.ko
staprun:main:431
modpath="/tmp/stapUpAWLw/stap_a78da046516a4f51cdefd2425658fc23_7467.ko",
modname="stap_a78da046516a4f51cdefd2425658fc23_7467"
staprun:init_staprun:337 init_staprun
staprun:insert_module:71 inserting module
/tmp/stapUpAWLw/stap_a78da046516a4f51cdefd2425658fc23_7467.ko
staprun:insert_module:97 module options: _stp_bufsize=0
staprun:insert_module:105 module path canonicalized to
'/tmp/stapUpAWLw/stap_a78da046516a4f51cdefd2425658fc23_7467.ko'
staprun:check_signature:418 checking signature for
/tmp/stapUpAWLw/stap_a78da046516a4f51cdefd2425658fc23_7467.ko
Signature file
/tmp/stapUpAWLw/stap_a78da046516a4f51cdefd2425658fc23_7467.ko.sgn not found
staprun:check_signature:431 verify_module returns 0
staprun:insert_module:168 Renaming module
'stap_a78da046516a4f51cdefd2425658fc23_7467'
staprun:insert_module:176 Renamed module to
'stap_a78da046516a4f51cdefd2425658fc23_5541'
staprun:insert_module:183 Module stap_a78da046516a4f51cdefd2425658fc23_5541
inserted from file
/tmp/stapUpAWLw/stap_a78da046516a4f51cdefd2425658fc23_7467.ko
staprun:init_ctl_channel:72 Opened
/sys/kernel/debug/systemtap/stap_a78da046516a4f51cdefd2425658fc23_5541/.cmd (4)
staprun:close_ctl_channel:112 Closed ctl fd 4
execing: /opt/codebase/install/libexec/systemtap/stapio -v -v -R -M 1
stap_a78da046516a4f51cdefd2425658fc23_5541 -F3 
stapio:parse_modpath:458
modpath="/lib/modules/4.1.6-201.fc22.x86_64/systemtap/stap_a78da046516a4f51cdefd2425658fc23_5541.ko"
stapio:main:50
modpath="/lib/modules/4.1.6-201.fc22.x86_64/systemtap/stap_a78da046516a4f51cdefd2425658fc23_5541.ko",
modname="stap_a78da046516a4f51cdefd2425658fc23_5541"
stapio:init_stapio:381 init_stapio
stapio:init_ctl_channel:30 Opened .cmd (4)
stapio:stp_main_loop:595 in main loop
stapio:stp_main_loop:614 select_supported: 1
stapio:cleanup_and_exit:474 detach=0
stapio:close_relayfs:440 closing
stapio:close_relayfs:462 done
stapio:cleanup_and_exit:491 closing control channel
stapio:close_ctl_channel:112 Closed ctl fd 4
stapio:cleanup_and_exit:499 
Renamed module to: stap_a78da046516a4f51cdefd2425658fc23_5541
stapio:cleanup_and_exit:506 removing stap_a78da046516a4f51cdefd2425658fc23_5541
staprun:parse_modpath:458
modpath="/lib/modules/4.1.6-201.fc22.x86_64/systemtap/stap_a78da046516a4f51cdefd2425658fc23_5541.ko"
staprun:main:431
modpath="/lib/modules/4.1.6-201.fc22.x86_64/systemtap/stap_a78da046516a4f51cdefd2425658fc23_5541.ko",
modname="stap_a78da046516a4f51cdefd2425658fc23_5541"
staprun:init_staprun:337 init_staprun
staprun:remove_module:246 stap_a78da046516a4f51cdefd2425658fc23_5541
staprun:init_ctl_channel:72 Opened
/sys/kernel/debug/systemtap/stap_a78da046516a4f51cdefd2425658fc23_5541/.cmd (4)
staprun:close_ctl_channel:112 Closed ctl fd 4
staprun:remove_module:271 removing module
stap_a78da046516a4f51cdefd2425658fc23_5541
Spawn waitpid result (0xff00): 255
WARNING: /opt/codebase/install/bin/staprun exited with signal: 127 (Unknown
signal 127)
Pass 5: run completed in 0usr/10sys/48real ms.
Pass 5: run failed.  [man error::pass5]
Running rm -rf /tmp/stapUpAWLw
Spawn waitpid result (0x0): 0
Removed temporary directory "/tmp/stapUpAWLw"

---------------------------------------------------------------------------

some /var/log/messages

Mar 16 14:02:31 flu kernel: BUG: unable to handle kernel NULL pointer
dereference at 0000000000000037
Mar 16 14:02:32 flu kernel: IP: [<ffffffff81304b36>] pde_subdir_find+0x16/0xa0
Mar 16 14:02:32 flu kernel: PGD 409ba4067 PUD 3bb297067 PMD 0
Mar 16 14:02:32 flu kernel: Oops: 0000 [#1] SMP
Mar 16 14:02:32 flu kernel: Modules linked in:
stap_255b2ce3b5de1fd0df5e4d4fb038a3a_11397(OE-) bnep bluetooth rfkill fuse
xt_CHECKSUM ipt_MASQUERADE nf_nat_masquerade_ipv4 tun nf_conntrack_netbios_ns
nf_conntrack_broadcast ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack
ebtable_nat ebtable_broute bridge 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 snd_hda_codec_realtek snd_hda_codec_generic snd_hda_codec_hdmi
snd_hda_intel snd_hda_controller snd_hda_codec snd_hda_core intel_rapl
snd_hwdep iosf_mbi snd_seq snd_seq_device snd_pcm x86_pkg_temp_thermal coretemp
iTCO_wdt kvm_intel iTCO_vendor_support
Mar 16 14:02:32 flu kernel: snd_timer dcdbas kvm snd shpchp crct10dif_pclmul
crc32_pclmul crc32c_intel ghash_clmulni_intel i2c_i801 soundcore mei_me mei
lpc_ich mfd_core nfsd auth_rpcgss nfs_acl lockd grace sunrpc binfmt_misc i915
serio_raw 8021q garp i2c_algo_bit stp llc drm_kms_helper mrp drm r8169 mii
video [last unloaded: stap_255b2ce3b5de1fd0df5e4d4fb038a3a_11387]
Mar 16 14:02:32 flu kernel: CPU: 3 PID: 11401 Comm: staprun-d Tainted: G       
   OE   4.1.6-201.fc22.x86_64+debug #1
Mar 16 14:02:32 flu kernel: Hardware name: Dell Inc. OptiPlex 3020/040DDP, BIOS
A06 11/17/2014
Mar 16 14:02:32 flu kernel: task: ffff88008fd6a660 ti: ffff880216260000
task.ti: ffff880216260000
Mar 16 14:02:32 flu kernel: RIP: 0010:[<ffffffff81304b36>] 
[<ffffffff81304b36>] pde_subdir_find+0x16/0xa0
Mar 16 14:02:32 flu kernel: RSP: 0018:ffff880216263d98  EFLAGS: 00010292
Mar 16 14:02:32 flu kernel: RAX: 0000000000000000 RBX: ffffffffffffffff RCX:
ef7bdef7bdef7bdf
Mar 16 14:02:32 flu kernel: RDX: 0000000000000000 RSI: ffff88039c99a0c9 RDI:
ffffffffffffffff
Mar 16 14:02:32 flu kernel: RBP: ffff880216263dc8 R08: 0000000000000000 R09:
0000000000000000
Mar 16 14:02:32 flu kernel: R10: 0000000000000001 R11: ffffffff81ea0b38 R12:
ffff88039c99a0c9
Mar 16 14:02:32 flu kernel: R13: ffffffffa06f36c0 R14: 0000000000000000 R15:
0000000000000000
Mar 16 14:02:32 flu kernel: FS:  00007f6bb712c740(0000)
GS:ffff88040f200000(0000) knlGS:0000000000000000
Mar 16 14:02:32 flu kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 16 14:02:32 flu kernel: CR2: 0000000000000037 CR3: 00000003e521f000 CR4:
00000000001426e0
Mar 16 14:02:32 flu kernel: Stack:
Mar 16 14:02:32 flu kernel: ffff880216263dc8 ffffffffffffffff ffff88039c99a0c9
ffffffffa06f36c0
Mar 16 14:02:32 flu kernel: 0000000000000000 0000000000000000 ffff880216263e28
ffffffff81305b54
Mar 16 14:02:32 flu kernel: 00000000ffffffff ffffffffffffffff ffff88039c99a0c9
0000000033c7839f
Mar 16 14:02:32 flu kernel: Call Trace:
Mar 16 14:02:32 flu kernel: [<ffffffff81305b54>] remove_proc_subtree+0x74/0x170
Mar 16 14:02:32 flu kernel: [<ffffffff81305c6e>] proc_remove+0x1e/0x30
Mar 16 14:02:32 flu kernel: [<ffffffffa06e6653>] _stp_close_procfs+0x33/0x50
[stap_255b2ce3b5de1fd0df5e4d4fb038a3a_11397]
Mar 16 14:02:32 flu kernel: [<ffffffffa06ece80>]
_stp_cleanup_and_exit+0x160/0x640 [stap_255b2ce3b5de1fd0df5e4d4fb038a3a_11397]
Mar 16 14:02:32 flu kernel: [<ffffffff812aa314>] ? mntput+0x24/0x40
Mar 16 14:02:32 flu kernel: [<ffffffff812b1e89>] ? simple_release_fs+0x49/0x60
Mar 16 14:02:32 flu kernel: [<ffffffffa06eec61>] cleanup_module+0x51/0xa0
[stap_255b2ce3b5de1fd0df5e4d4fb038a3a_11397]
Mar 16 14:02:32 flu kernel: [<ffffffff8115c6ef>] SyS_delete_module+0x1cf/0x280
Mar 16 14:02:32 flu kernel: [<ffffffff8189e82e>] system_call_fastpath+0x12/0x76
Mar 16 14:02:32 flu kernel: Code: 89 e5 48 8b 40 58 5d c3 66 66 66 66 2e 0f 1f
84 00 00 00 00 00 0f 1f 44 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 53 48 83
ec 08 <48> 8b 5f 38 48 85 db 74 4d 41 89 d6 49 89 f5 4d 89 f4 eb 0f 66
Mar 16 14:02:32 flu kernel: RIP  [<ffffffff81304b36>] pde_subdir_find+0x16/0xa0
Mar 16 14:02:32 flu kernel: RSP <ffff880216263d98>
Mar 16 14:02:32 flu kernel: CR2: 0000000000000037
Mar 16 14:02:32 flu kernel: ---[ end trace 8e819e560920024a ]---

---------------------------------------------------------------------------------------

Mar 16 12:21:03 flu kernel: NMI watchdog: BUG: soft lockup - CPU#2 stuck for
22s! [systemd-udevd:3812]
Mar 16 12:21:04 flu kernel: Modules linked in:
stap_b710ef1c031f7e0f98bf4fd73321e432_4038(OE+)
stap_b710ef1c031f7e0f98bf4fd73321e432_4031(OE-) uinput bnep bluetooth rfkill
fuse xt_CHECKSUM ipt_MASQUERADE nf_nat_masquerade_ipv4 tun nf_con
Mar 16 12:21:04 flu kernel:  ghash_clmulni_intel snd_timer snd i2c_piix4
parport_pc virtio_balloon parport soundcore acpi_cpufreq nfsd auth_rpcgss
nfs_acl lockd grace sunrpc virtio_console 8139too 8021q garp stp llc mrp qxl
drm_kms_helpe
Mar 16 12:21:04 flu kernel: CPU: 2 PID: 3812 Comm: systemd-udevd Tainted: G    
 D    OE   4.1.6-201.fc22.x86_64 #1
Mar 16 12:21:04 flu kernel: Hardware name: QEMU Standard PC (i440FX + PIIX,
1996), BIOS 1.8.1-20150318_183358- 04/01/2014
Mar 16 12:21:04 flu kernel: task: ffff88009ba209e0 ti: ffff880092798000
task.ti: ffff880092798000
Mar 16 12:21:04 flu kernel: RIP: 0010:[<ffffffff8179fd17>] 
[<ffffffff8179fd17>] _raw_spin_lock+0x37/0x50
Mar 16 12:21:04 flu kernel: RSP: 0018:ffff88009279bbd8  EFLAGS: 00000206
Mar 16 12:21:04 flu kernel: RAX: 0000000000003c50 RBX: 0000000000000000 RCX:
00000000000016e1
Mar 16 12:21:04 flu kernel: RDX: 00000000000016e0 RSI: ffff88013ac2c038 RDI:
ffffffff8200c0b0
Mar 16 12:21:04 flu kernel: RBP: ffff88009279bbd8 R08: 0000000000000007 R09:
ffff880098a14840
Mar 16 12:21:04 flu kernel: R10: 2f2f2f2f2f2f2f2f R11: 0000000000000000 R12:
ffffffff00000000
Mar 16 12:21:04 flu kernel: R13: 001fffff9279bb68 R14: 0000000000000000 R15:
ffff88009279bdf8
Mar 16 12:21:04 flu kernel: FS:  00007f433f516880(0000)
GS:ffff88013fd00000(0000) knlGS:0000000000000000
Mar 16 12:21:04 flu kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 16 12:21:04 flu kernel: CR2: 0000000000567570 CR3: 000000008f0cb000 CR4:
00000000001406e0
Mar 16 12:21:04 flu kernel: Stack:
Mar 16 12:21:04 flu kernel:  ffff88009279bc08 ffffffff8129dc57 ffff88009279bd07
ffff88013ac2c038
Mar 16 12:21:04 flu kernel:  ffff880098a14840 0000000000000101 ffff88009279bc18
ffffffff8129dd0b
Mar 16 12:21:04 flu kernel:  ffff88009279bc48 ffffffff812987e3 ffff88009279bc78
ffff880098a14840
Mar 16 12:21:04 flu kernel: Call Trace:
Mar 16 12:21:04 flu kernel:  [<ffffffff8129dc57>] proc_lookup_de+0x27/0xc0
Mar 16 12:21:04 flu kernel:  [<ffffffff8129dd0b>] proc_lookup+0x1b/0x20
Mar 16 12:21:04 flu kernel:  [<ffffffff812987e3>] proc_root_lookup+0x33/0x40
Mar 16 12:21:04 flu kernel:  [<ffffffff81234c7d>] lookup_real+0x1d/0x70
Mar 16 12:21:04 flu kernel:  [<ffffffff8123a39c>] do_last+0xb5c/0x1330
Mar 16 12:21:04 flu kernel:  [<ffffffff8123ba8f>] path_openat+0x8f/0x680
Mar 16 12:21:04 flu kernel:  [<ffffffff81272960>] ?
ep_read_events_proc+0xd0/0xd0
Mar 16 12:21:04 flu kernel:  [<ffffffff8123d6d9>] do_filp_open+0x49/0xd0
Mar 16 12:21:04 flu kernel:  [<ffffffff813c28fa>] ?
find_next_zero_bit+0x1a/0x30
Mar 16 12:21:04 flu kernel:  [<ffffffff8124a50e>] ? __alloc_fd+0x7e/0x120
Mar 16 12:21:04 flu kernel:  [<ffffffff8122a02a>] do_sys_open+0x13a/0x250
Mar 16 12:21:04 flu kernel:  [<ffffffff8122a15e>] SyS_open+0x1e/0x20
Mar 16 12:21:04 flu kernel:  [<ffffffff817a002e>]
system_call_fastpath+0x12/0x71
Mar 16 12:21:04 flu kernel: Code: 01 00 f0 0f c1 07 89 c2 c1 ea 10 66 39 c2 75
04 5d c3 66 90 89 d1 b8 00 80 00 00 eb 0e 0f 1f 80 00 00 00 00 f3 90 83 e8 01
74 eb <0f> b7 17 66 39 ca 75 f1 5d c3 66 66 66 66 66 66 2e 0f 1f 84 00

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/19833] monitor mode causes kernel crash when exited immediately

[flu at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=19833

--- Comment #1 from Felix Lu <flu at redhat dot com> ---
This is found to be caused by the usage of cleanup_and_exit() in
staprun/monitor.c. Commit abc8b01fbd063d6a8076953d82ebd6c4c7e65d6d removes this
usage but the bug persists somewhere.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/19833] monitor mode causes kernel crash when exited immediately

[flu at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=19833

--- Comment #2 from Felix Lu <flu at redhat dot com> ---
The order of procfs file removal when using cleanup_and_exit() seems to be
wrong.

Proper exit:

$ stap -vve 'probe procfs("file1").read {println("file1")} probe
procfs("file2").read{println("file2")}'

$ stap -vve 'probe kernel.function("remove_proc_subtree") {println($$vars)
println(kernel_string($name))}

Pass 5: starting run.
Running /opt/codebase/install/bin/staprun -v -R
/tmp/stapsevTUs/stap_64aaee2df74482eec00fd5d7e412c6de_4493.ko
staprun:insert_module:183 Module stap_64aaee2df74482eec00fd5d7e412c6d_22426
inserted from file
/tmp/stapsevTUs/stap_64aaee2df74482eec00fd5d7e412c6de_4493.ko
name=0xffff88006346fa45 parent=0xffff880062b13e40 root=? de=? next=?
fn=0xffff8800621c3d20 len=?
file2
name=0xffff88006346f685 parent=0xffff880062b13e40 root=? de=? next=?
fn=0xffff8800621c3d20 len=?
file1
name=0xffff880062b13ec5 parent=0xffff880139dfbc00 root=? de=? next=?
fn=0xffff8800621cfed0 len=?
stap_de015c12e52d8c7258bb2e8842dbb42_22414

The stap module proc folder is cleaned up after the files in this case.

-------------------------------------------------------------------------------

Using cleanup_and_exit():

$ stap --monitor -ve 'probe begin {println(1)}'

$ stap -vve 'probe kernel.function("remove_proc_subtree") {println($$vars)
println(kernel_string($name))}

Pass 5: starting run.
Running /opt/codebase/install/bin/staprun -v -R
/tmp/stapMXpr4y/stap_64aaee2df74482eec00fd5d7e412c6de_4493.ko
staprun:insert_module:183 Module stap_64aaee2df74482eec00fd5d7e412c6d_22447
inserted from file
/tmp/stapMXpr4y/stap_64aaee2df74482eec00fd5d7e412c6de_4493.ko
name=0xffff8800a1f8c805 parent=0xffff880139dfbc00 root=? de=? next=?
fn=0xffff88011aca3ed0 len=?
stap_438e1eb967615a30bf68838470e3126_22755
name=0xffff880138ce8205 parent=0xffff8800a1f8c780 root=? de=? next=?
fn=0xffff88011aca3e40 len=?
monitor_status
name=0xffff880138ce8b05 parent=0xffff8800a1f8c780 root=? de=? next=?
fn=0xffff88011aca3e40 len=?
monitor_control

In this case, the module proc folder is cleaned up before the subtree,
which is likely to be the cause of the crash.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/19833] monitor mode causes kernel crash when exited immediately

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=19833

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |fche at redhat dot com

--- Comment #3 from Frank Ch. Eigler <fche at redhat dot com> ---
The difference appears to be the presence or absence of an STP_EXIT packet
being sent to the module.  In the staprun monitor.c-'q'-invoked cleanup, there
was no STP_EXIT packet, thus the cleanup_module() /
systemtap_kernel_module_exit() path only was taken.  This does not include the
STP_EXIT handling (systemtap_module_exit), which is a bug.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/19833] monitor mode causes kernel crash when exited immediately

[fche at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=19833

Frank Ch. Eigler <fche at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

--- Comment #4 from Frank Ch. Eigler <fche at redhat dot com> ---
The root cause appears corrected via commit 909ccbfa8674e.
See also bug #15408.

-- 
You are receiving this mail because:
You are the assignee for the bug.