[Bug runtime/31500] New: stapio exited with irqs disabled

[Bug runtime/31500] New: stapio exited with irqs disabled

[mcermak at redhat dot com]

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

            Bug ID: 31500
           Summary: stapio exited with irqs disabled
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
          Assignee: systemtap at sourceware dot org
          Reporter: mcermak at redhat dot com
  Target Milestone: ---

With systemtap commit b67f0fc38bd5139eda809eef12e20568e140cd96  I'm hitting
testsuite stalls.  Reproducing it takes ~hours, but seems reliable.  I've
reproduced with both rawhide and rawhide-debug kernel. The results and output
are pretty similar for both kernels.  The following is with 
6.9.0-0.rc0.20240314git480e035fc4c7.5.fc41.x86_64+debug:



[root@rawh ~]# pstree -p 62459
make(62459)───make(62462)───make(62463)───sh(62465)───expect(62486)─┬─bash(122503)
                                                                   
├─stap(62728)
                                                                   
├─stap(115557)
                                                                   
├─stap(180093)
                                                                   
├─stap(187657)───stapio(188000)─┬─{stapio}(188002)
                                                                    │          
                    ├─{stapio}(188003)
                                                                    │          
                    └─{stapio}(188004)
                                                                   
└─{expect}(62570)
[root@rawh ~]# fgrep -i stat /proc/187657/status 
State:  S (sleeping)
[root@rawh ~]# fgrep -i stat /proc/188000/status 
State:  Z (zombie)
[root@rawh ~]# 
[root@rawh ~]# gdb -q -p 187657
[ ... stuff deleted ... ]
(gdb) bt
#0  0x00007fed601a9d67 in wait4 () from /lib64/libc.so.6
#1  0x00000000005cb8e4 in stap_waitpid (verbose=0, pid=188000) at
../systemtap/util.cxx:843
#2  0x0000000000633647 in direct::finish (this=0x288e3650) at
../systemtap/remote.cxx:108
#3  0x0000000000630e2a in remote::run (remotes=std::vector of length 1,
capacity 1 = {...}) at /usr/include/c++/14/bits/stl_vector.h:1144
#4  0x0000000000471513 in pass_5 (s=..., targets=std::vector of length 1,
capacity 1 = {...}) at ../systemtap/main.cxx:1388
#5  0x000000000046e1fc in main (argc=<optimized out>, argv=<optimized out>) at
../systemtap/main.cxx:1632
(gdb) 

[root@rawh ~]# dmesg
[ ... stuff deleted ... ]
[16452.731796]  stap_e4ade712b5a11cfdd0af14bfb4224df_29278(OE):1
stap_79325b69980582f86b9f5ee4e671bb2_28895(OE):1
stap_573cd5889b91236242ba1206224b1da_28519(OE):1
stap_5f829f7d6b934c4dc34166cf5f4dd80_28143(OE):1
stap_fccbe5e083add72333593aa0f6f816a_27756(OE):1
stap_4eac1dd011efe3e75bda066643b8fc4_27393(OE):1
stap_e24b147733cae10e2828c6dc6c87e3b_27041(OE):1
stap_f997e949c73eb99bae83fb21536da40_26689(OE):1
stap_618c87c4017e4ef8e4ecab83485453d_26301(OE):1
stap_ed0cedb34bc4ae619f54c37359c9f10_25938(OE):1
stap_08b6656b42c733b8993924f59cb76f9_25590(OE):1
stap_ee610f07e1b09c16176db7708c65f16_25242(OE):1
stap_6b57ff065036442445cb7eb5dc87546_24879(OE):1
stap_a07e0fe7a94e704368e383634645c3c_24517(OE):1
stap_e9b8c009da3cb8a321d6a6acc5ddfde_24152(OE):1
stap_f45886cc2f74a0200690ea946ee1e50_23791(OE):1
stap_cc682057afce0d071203c2ad97390340_23365(OE):1
stap_2153c65d83f86cce8412b1b1e442165f_22773(OE):1 [last unloaded:
stap_017c8012d60fc7fd31a84d27b5a28d_187649(OE)]
[16452.767193] CR2: ffffffffa64a65c0
[16452.769368] ---[ end trace 0000000000000000 ]---
[16452.771499] RIP: 0010:arch_adjust_kprobe_addr+0x41/0xe0
[16452.773611] Code: 48 89 d3 48 ba 00 00 00 00 00 fc ff df 48 83 ec 08 0f b6
0c 11 48 89 fa 83 e2 07 83 c2 03 38 ca 7c 08 84 c9 0f 85 85 00 00 00 <8b> 55 00
81 fa 66 0f 1f 00 74 4f 81 e2 ff ff ff fe b9 0c f0 e1 05
[16452.777850] RSP: 0018:ffffc90002027960 EFLAGS: 00010246
[16452.779941] RAX: 0000000000000001 RBX: ffffc90002027a58 RCX:
0000000000000000
[16452.782014] RDX: 0000000000000003 RSI: 0000000000000000 RDI:
ffffffffa64a65c0
[16452.784058] RBP: ffffffffa64a65c0 R08: fffffbfff4858cff R09:
0000000000000000
[16452.786089] R10: 0000000000000000 R11: 0000000000000001 R12:
1ffff92000404f31
[16452.788180] R13: ffffffffc10ca498 R14: 0000000000000000 R15:
ffffffffc20ada98
[16452.790166] FS:  00007f1eaa74a180(0000) GS:ffff888115400000(0000)
knlGS:0000000000000000
[16452.792138] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[16452.794077] CR2: ffffffffa64a65c0 CR3: 000000010e99e005 CR4:
0000000000370ef0
[16452.796007] DR0: 0000000000404010 DR1: 0000000000000000 DR2:
0000000000000000
[16452.797910] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000600
[16452.799774] note: stapio[188000] exited with irqs disabled
[17353.035208] workqueue: drain_vmap_area_work hogged CPU for >10000us 1027
times, consider switching to WQ_UNBOUND
[22491.638101] workqueue: drain_vmap_area_work hogged CPU for >10000us 2051
times, consider switching to WQ_UNBOUND
[32865.163317] workqueue: drain_vmap_area_work hogged CPU for >10000us 4099
times, consider switching to WQ_UNBOUND
[41530.296260] clocksource: timekeeping watchdog on CPU1: kvm-clock retried 1
times before success
[53438.316931] workqueue: drain_vmap_area_work hogged CPU for >10000us 8195
times, consider switching to WQ_UNBOUND
[root@rawh ~]#

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

William Cohen <wcohen at redhat dot com> changed:

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

--- Comment #1 from William Cohen <wcohen at redhat dot com> ---
This being encountered in during a regular "make installcheck"? Or are multiple
runs requireed to trigger this?

Is this running inside a guest VM or bare hardware?

How many cores does the machine running the tests have?

Does the problem go away when the number of available cores is reduced (or even
limited to 1)?

I wonder if the "stapio[188000] exited with irqs disabled" is causing the
"workqueue: drain_vmap_area_work hogged CPU for ..." messages.

It would also be good to fully understand the following in the dmesg output. 
What is CR2 (and CR3/CR4 etc.) referring to:

[16452.767193] CR2: ffffffffa64a65c0
[16452.769368] ---[ end trace 0000000000000000 ]---
[16452.771499] RIP: 0010:arch_adjust_kprobe_addr+0x41/0xe0
[16452.773611] Code: 48 89 d3 48 ba 00 00 00 00 00 fc ff df 48 83 ec 08 0f b6
0c 11 48 89 fa 83 e2 07 83 c2 03 38 ca 7c 08 84 c9 0f 85 85 00 00 00 <8b> 55 00
81 fa 66 0f 1f 00 74 4f 81 e2 ff ff ff fe b9 0c f0 e1 05
[16452.777850] RSP: 0018:ffffc90002027960 EFLAGS: 00010246
[16452.779941] RAX: 0000000000000001 RBX: ffffc90002027a58 RCX:
0000000000000000
[16452.782014] RDX: 0000000000000003 RSI: 0000000000000000 RDI:
ffffffffa64a65c0
[16452.784058] RBP: ffffffffa64a65c0 R08: fffffbfff4858cff R09:
0000000000000000
[16452.786089] R10: 0000000000000000 R11: 0000000000000001 R12:
1ffff92000404f31
[16452.788180] R13: ffffffffc10ca498 R14: 0000000000000000 R15:
ffffffffc20ada98
[16452.790166] FS:  00007f1eaa74a180(0000) GS:ffff888115400000(0000)
knlGS:0000000000000000
[16452.792138] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[16452.794077] CR2: ffffffffa64a65c0 CR3: 000000010e99e005 CR4:
0000000000370ef0
[16452.796007] DR0: 0000000000404010 DR1: 0000000000000000 DR2:
0000000000000000
[16452.797910] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000600
[16452.799774] note: stapio[188000] exited with irqs disabled

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

[Bug runtime/31500] stapio exited with irqs disabled

[mcermak at redhat dot com]

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

--- Comment #2 from Martin Cermak <mcermak at redhat dot com> ---
(In reply to William Cohen from comment #1)
> This being encountered in during a regular "make installcheck"? Or are
> multiple runs requireed to trigger this?

Yup, for me this happens once or twice per a "make installcheck" run.

> Is this running inside a guest VM or bare hardware?
>
> How many cores does the machine running the tests have?
> 
> Does the problem go away when the number of available cores is reduced (or
> even limited to 1)?

It's my local VM.  Originally it had 2 cores, but I've lowered it down to 1
core and reproduced again:

[ 5286.549884] CR2: ffffffffaed64670
[ 5286.550344] ---[ end trace 0000000000000000 ]---
[ 5286.550792] RIP: 0010:arch_adjust_kprobe_addr+0x9/0x60
[ 5286.551245] Code: cc cc cc 48 89 de 48 89 ef 5b 5d e9 01 f9 ff ff 90 90 90
90 90 90 90 90 90 90 90 90 90 90 90 90 90 66 0f 1f 00 0f 1f 44 00 00 <8b> 07 3d
66 0f 1f 00 74 24 25 ff ff ff fe 41 b8 0c f0 e1 05 41 f7
[ 5286.552147] RSP: 0018:ffffb41641d67cb0 EFLAGS: 00010282
[ 5286.552592] RAX: 0000000000000001 RBX: ffffffffaed64670 RCX:
ffffffffaed64670
[ 5286.553040] RDX: ffffb41641d67ce7 RSI: 0000000000000000 RDI:
ffffffffaed64670
[ 5286.553478] RBP: ffffb41641d67ce7 R08: 0000000000000000 R09:
ffffb41641d67cb8
[ 5286.553914] R10: 0000000000034132 R11: fffffffffd29b98f R12:
0000000000000000
[ 5286.554341] R13: ffffffffc09645f0 R14: 0000000000000000 R15:
ffffffffc09651c0
[ 5286.554764] FS:  00007f3bb1d6b180(0000) GS:ffff9083b8400000(0000)
knlGS:0000000000000000
[ 5286.555192] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 5286.555611] CR2: ffffffffaed64670 CR3: 000000001687e004 CR4:
0000000000370ef0
[ 5286.556034] DR0: 0000000000404010 DR1: 0000000000000000 DR2:
0000000000000000
[ 5286.556444] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000600
[ 5286.556862] note: stapio[128685] exited with irqs disabled
[10845.009756] clocksource: timekeeping watchdog on CPU0: kvm-clock retried 1
times before success

> I wonder if the "stapio[188000] exited with irqs disabled" is causing the
> "workqueue: drain_vmap_area_work hogged CPU for ..." messages.
> 
> It would also be good to fully understand the following in the dmesg output.
> What is CR2 (and CR3/CR4 etc.) referring to:
> 
> [16452.767193] CR2: ffffffffa64a65c0
> [16452.769368] ---[ end trace 0000000000000000 ]---
> [16452.771499] RIP: 0010:arch_adjust_kprobe_addr+0x41/0xe0
> [16452.773611] Code: 48 89 d3 48 ba 00 00 00 00 00 fc ff df 48 83 ec 08 0f
> b6 0c 11 48 89 fa 83 e2 07 83 c2 03 38 ca 7c 08 84 c9 0f 85 85 00 00 00 <8b>
> 55 00 81 fa 66 0f 1f 00 74 4f 81 e2 ff ff ff fe b9 0c f0 e1 05
> [16452.777850] RSP: 0018:ffffc90002027960 EFLAGS: 00010246
> [16452.779941] RAX: 0000000000000001 RBX: ffffc90002027a58 RCX:
> 0000000000000000
> [16452.782014] RDX: 0000000000000003 RSI: 0000000000000000 RDI:
> ffffffffa64a65c0
> [16452.784058] RBP: ffffffffa64a65c0 R08: fffffbfff4858cff R09:
> 0000000000000000
> [16452.786089] R10: 0000000000000000 R11: 0000000000000001 R12:
> 1ffff92000404f31
> [16452.788180] R13: ffffffffc10ca498 R14: 0000000000000000 R15:
> ffffffffc20ada98
> [16452.790166] FS:  00007f1eaa74a180(0000) GS:ffff888115400000(0000)
> knlGS:0000000000000000
> [16452.792138] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [16452.794077] CR2: ffffffffa64a65c0 CR3: 000000010e99e005 CR4:
> 0000000000370ef0
> [16452.796007] DR0: 0000000000404010 DR1: 0000000000000000 DR2:
> 0000000000000000
> [16452.797910] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
> 0000000000000600
> [16452.799774] note: stapio[188000] exited with irqs disabled

"CR2" is mentioned twice in the new dmesg snippet I've added to this comment
above.  Looking up my dmesg, it's mentioned there once again earlier. It seems
to refer to a page fault:


[ 5286.379371] stap_3727aef4065cf8a32c15be31b4bdef0_128685 (poll_map.stp):
systemtap: 5.1/0.191, base: ffffffffc08cc000, memory:
3744data/72text/15ctx/16486net/2247alloc kb, probes: 80
[ 5286.479244] BUG: unable to handle page fault for address: ffffffffaed64670
[ 5286.479272] #PF: supervisor read access in kernel mode
[ 5286.479280] #PF: error_code(0x0000) - not-present page
[ 5286.479288] PGD 2d427067 P4D 2d427067 PUD 2d428063 PMD 1052c3063 PTE
800fffffd229b062
[ 5286.479302] Oops: 0000 [#1] PREEMPT SMP PTI
[ 5286.479310] CPU: 0 PID: 128685 Comm: stapio Tainted: G           OE    
-------  ---  6.9.0-0.rc0.20240313gitb0546776ad3f.4.fc41.x86_64 #1
[ 5286.479327] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS
1.16.1-2.fc36 04/01/2014
[ 5286.479338] RIP: 0010:arch_adjust_kprobe_addr+0x9/0x60
[ 5286.479349] Code: cc cc cc 48 89 de 48 89 ef 5b 5d e9 01 f9 ff ff 90 90 90
90 90 90 90 90 90 90 90 90 90 90 90 90 90 66 0f 1f 00 0f 1f 44 00 00 <8b> 07 3d
66 0f 1f 00 74 24 25 ff ff ff fe 41 b8 0c f0 e1 05 41 f7
[ 5286.479371] RSP: 0018:ffffb41641d67cb0 EFLAGS: 00010282
[ 5286.479379] RAX: 0000000000000001 RBX: ffffffffaed64670 RCX:
ffffffffaed64670
[ 5286.479389] RDX: ffffb41641d67ce7 RSI: 0000000000000000 RDI:
ffffffffaed64670
[ 5286.479399] RBP: ffffb41641d67ce7 R08: 0000000000000000 R09:
ffffb41641d67cb8
[ 5286.479408] R10: 0000000000034132 R11: fffffffffd29b98f R12:
0000000000000000
[ 5286.479418] R13: ffffffffc09645f0 R14: 0000000000000000 R15:
ffffffffc09651c0
[ 5286.479427] FS:  00007f3bb1d6b180(0000) GS:ffff9083b8400000(0000)
knlGS:0000000000000000
[ 5286.479438] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 5286.479446] CR2: ffffffffaed64670 CR3: 000000001687e004 CR4:
0000000000370ef0
[ 5286.479459] DR0: 0000000000404010 DR1: 0000000000000000 DR2:
0000000000000000
[ 5286.479471] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000600
[ 5286.479481] Call Trace:
[ 5286.479486]  <TASK>
[ 5286.479491]  ? __die+0x23/0x70
[ 5286.479498]  ? __pfx_vfs_caches_init_early+0x10/0x10
[ 5286.479507]  ? page_fault_oops+0x170/0x580
[ 5286.479515]  ? __pfx_vfs_caches_init_early+0x10/0x10
[ 5286.479524]  ? exc_page_fault+0x170/0x180
[ 5286.479532]  ? asm_exc_page_fault+0x26/0x30
[ 5286.479542]  ? __pfx_vfs_caches_init_early+0x10/0x10
[ 5286.479551]  ? __pfx_vfs_caches_init_early+0x10/0x10
[ 5286.479559]  ? __pfx_vfs_caches_init_early+0x10/0x10
[ 5286.479566]  ? arch_adjust_kprobe_addr+0x9/0x60
[ 5286.479575]  _kprobe_addr+0x64/0x90
[ 5286.479582]  register_kprobe+0x42/0x6a0
[ 5286.479590]  stapkp_register_probe+0x124/0x180
[stap_3727aef4065cf8a32c15be31b4bdef0_128685]
[ 5286.479610]  _stp_ctl_write_cmd+0x1037/0x2390
[stap_3727aef4065cf8a32c15be31b4bdef0_128685]
[ 5286.479629]  ? inode_security+0x22/0x60
[ 5286.479637]  ? selinux_file_permission+0x14f/0x180
[ 5286.479646]  proc_reg_write+0x59/0xa0
[ 5286.479653]  vfs_write+0xf5/0x460
[ 5286.479660]  ? __do_sys_clone3+0xe4/0x120
[ 5286.479669]  ? _copy_from_user+0x2f/0x70
[ 5286.479944]  ? __x64_sys_rt_sigprocmask+0xdb/0x150
[ 5286.480205]  ksys_write+0x6d/0xf0
[ 5286.480456]  do_syscall_64+0x85/0x170
[ 5286.480704]  ? syscall_exit_to_user_mode+0x69/0x220
[ 5286.480954]  ? do_syscall_64+0x94/0x170
[ 5286.481193]  ? exc_page_fault+0x7e/0x180
[ 5286.481432]  entry_SYSCALL_64_after_hwframe+0x6c/0x74
[ 5286.481669] RIP: 0033:0x7f3bb1e777fd
[ 5286.481918] Code: e5 48 83 ec 20 48 89 55 e8 48 89 75 f0 89 7d f8 e8 08 6a
f8 ff 48 8b 55 e8 48 8b 75 f0 41 89 c0 8b 7d f8 b8 01 00 00 00 0f 05 <48> 3d 00
f0 ff ff 77 33 44 89 c7 48 89 45 f8 e8 5f 6a f8 ff 48 8b
[ 5286.482399] RSP: 002b:00007ffc3dd21c60 EFLAGS: 00000293 ORIG_RAX:
0000000000000001
[ 5286.482640] RAX: ffffffffffffffda RBX: 0000000000000008 RCX:
00007f3bb1e777fd
[ 5286.482893] RDX: 000000000000000c RSI: 00007ffc3dd21c90 RDI:
0000000000000004
[ 5286.483126] RBP: 00007ffc3dd21c80 R08: 0000000000000000 R09:
00007ffc3dd20e57
[ 5286.483351] R10: 0000000000000008 R11: 0000000000000293 R12:
00007ffc3dd22120
[ 5286.483572] R13: 00007ffc3dd221a4 R14: 0000000000000001 R15:
00007ffc3dd22100
[ 5286.483793]  </TASK>
[ 5286.484014] Modules linked in:
stap_3727aef4065cf8a32c15be31b4bdef0_128685(OE)
stap_5f2af8997e31ed2aec4c86ba029f24e_16223(OE)
stap_09721f51216043267ec96771bff9046_14182(OE) intel_rapl_msr intel_rapl_common
intel_pmc_core intel_vsec pmt_telemetry pmt_class kvm_intel
snd_hda_codec_generic snd_hda_intel snd_intel_dspcfg kvm snd_intel_sdw_acpi
snd_hda_codec snd_hda_core snd_hwdep snd_seq snd_seq_device snd_pcm irqbypass
rapl iTCO_wdt intel_pmc_bxt iTCO_vendor_support rfkill snd_timer i2c_i801 snd
i2c_smbus lpc_ich soundcore virtio_net joydev virtio_balloon net_failover
failover sunrpc loop fuse nfnetlink zram crct10dif_pclmul crc32_pclmul
crc32c_intel polyval_clmulni polyval_generic ghash_clmulni_intel sha512_ssse3
sha256_ssse3 virtio_console sha1_ssse3 virtio_gpu virtio_blk virtio_dma_buf
serio_raw qemu_fw_cfg


AI seems to be suggesting me that CR is a special purpose "control" register
typically holding the address that caused a page fault on x86_64.

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

--- Comment #3 from William Cohen <wcohen at redhat dot com> ---
The dmesg output is stating a page fault occurred.  CR2 holds the page-fault
linear address the access was attemtped on.  This was occurring in the
arch_adjust_kprobe_addr function.  On the x86_64 this function has to move
kprobes past the ENDBR instuction that is a target for a branch. If IBT
enabled, and the target of indirect branch is not an ENBR, it will be trapped
and killed.  The "Code:" section show what the code looks like.
The "<8b> 55 00" is the instruction which is a "mov 0x0(%rbp), %edx".  The
following dump of the registers show RBP has ffffffffa64a65c0, the same value
as CR2.  It looks like a bogus address is being used for a kprobe.  Are these
dmesgs showing up consistently around the same places in the "make
installcheck" runs (assuming not rebooting the system)?

It might be possible that the irq are disabled when the arch_adjust_kprobe_addr
function is running and when the stapio exits it makes a not of it
https://elixir.bootlin.com/linux/v6.8.1/source/kernel/exit.c#L944 .

stap_017c8012d60fc7fd31a84d27b5a28d_187649(OE)]
[16452.767193] CR2: ffffffffa64a65c0
[16452.769368] ---[ end trace 0000000000000000 ]---
[16452.771499] RIP: 0010:arch_adjust_kprobe_addr+0x41/0xe0
[16452.773611] Code: 48 89 d3 48 ba 00 00 00 00 00 fc ff df 48 83 ec 08 0f b6
0c 11 48 89 fa 83 e2 07 83 c2 03 38 ca 7c 08 84 c9 0f 85 85 00 00 00 <8b> 55 00
81 fa 66 0f 1f 00 74 4f 81 e2 ff ff ff fe b9 0c f0 e1 05
[16452.777850] RSP: 0018:ffffc90002027960 EFLAGS: 00010246
[16452.779941] RAX: 0000000000000001 RBX: ffffc90002027a58 RCX:
0000000000000000
[16452.782014] RDX: 0000000000000003 RSI: 0000000000000000 RDI:
ffffffffa64a65c0
[16452.784058] RBP: ffffffffa64a65c0 R08: fffffbfff4858cff R09:
0000000000000000
[16452.786089] R10: 0000000000000000 R11: 0000000000000001 R12:
1ffff92000404f31
[16452.788180] R13: ffffffffc10ca498 R14: 0000000000000000 R15:
ffffffffc20ada98
[16452.790166] FS:  00007f1eaa74a180(0000) GS:ffff888115400000(0000)
knlGS:0000000000000000
[16452.792138] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[16452.794077] CR2: ffffffffa64a65c0 CR3: 000000010e99e005 CR4:
0000000000370ef0
[16452.796007] DR0: 0000000000404010 DR1: 0000000000000000 DR2:
0000000000000000
[16452.797910] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000600
[16452.799774] note: stapio[188000] exited with irqs disabled

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

--- Comment #4 from William Cohen <wcohen at redhat dot com> ---
I have a specific f39 x86_64 machine that seems to encounter a similar problem
with the poll_map.exp test both running on the bare hardware and on a guest VM.
 poll_map.exp times out and the dmesg output has:

[ 4631.997499] kprobes: kprobe jump-optimization is disabled. All kprobes are
based on software breakpoint.
[ 4632.028908] stap_7d90e889b82f98d2135859abdd7b9927_53381: loading out-of-tree
module taints kernel.
[ 4632.028913] stap_7d90e889b82f98d2135859abdd7b9927_53381: module verification
failed: signature and/or required key missing - tainting kernel
[ 4632.120180] stap_7d90e889b82f98d2135859abdd7b9927_53381 (poll_map.stp):
systemtap: 5.1/0.191, base: ffffffffc1f2c000, memory:
3716data/72text/127ctx/131174net/2330alloc kb, probes: 80
[ 4632.225659] BUG: unable to handle page fault for address: ffffffffbad48280
[ 4632.225662] #PF: supervisor read access in kernel mode
[ 4632.225664] #PF: error_code(0x0000) - not-present page
[ 4632.225665] PGD 3ea427067 P4D 3ea427067 PUD 3ea428063 PMD 10d537063 PTE
800ffffc152b7062
[ 4632.225669] Oops: 0000 [#1] PREEMPT SMP PTI
[ 4632.225671] CPU: 7 PID: 53381 Comm: stapio Tainted: G           OE     
6.7.9-200.fc39.x86_64 #1
[ 4632.225674] Hardware name: LENOVO 20HHCTO1WW/20HHCTO1WW, BIOS N1UET89W (1.63
) 11/14/2023
[ 4632.225675] RIP: 0010:arch_adjust_kprobe_addr+0x9/0x60
[ 4632.225679] Code: cc cc cc 48 89 de 48 89 ef 5b 5d e9 f1 f8 ff ff 90 90 90
90 90 90 90 90 90 90 90 90 90 90 90 90 90 66 0f 1f 00 0f 1f 44 00 00 <8b> 07 3d
66 0f 1f 00 74 24 25 ff ff ff fe 41 b8 0c f0 e1 05 41 f7
[ 4632.225681] RSP: 0018:ffffc26e47b67c38 EFLAGS: 00010282
[ 4632.225696] RAX: 0000000000000001 RBX: ffffffffbad48280 RCX:
ffffffffbad48280
[ 4632.225697] RDX: ffffc26e47b67c6f RSI: 0000000000000000 RDI:
ffffffffbad48280
[ 4632.225699] RBP: ffffc26e47b67c6f R08: fffffffffd2b7d7f R09:
ffffc26e47b67c40
[ 4632.225700] R10: 0000000000000000 R11: 0000000000033a98 R12:
0000000000000000
[ 4632.225701] R13: 0000000000000000 R14: 0000000000000000 R15:
ffffffffc1f40db0
[ 4632.225702] FS:  00007f9040a2e140(0000) GS:ffff9fcc8f9c0000(0000)
knlGS:0000000000000000
[ 4632.225716] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 4632.225718] CR2: ffffffffbad48280 CR3: 000000024e98e001 CR4:
00000000003706f0
[ 4632.225719] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[ 4632.225720] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[ 4632.225721] Call Trace:
[ 4632.225723]  <TASK>
[ 4632.225724]  ? __die+0x23/0x70
[ 4632.225727]  ? __pfx_vfs_caches_init+0x10/0x10
[ 4632.225729]  ? page_fault_oops+0x171/0x4e0
[ 4632.225733]  ? __pfx_vfs_caches_init+0x10/0x10
[ 4632.225735]  ? exc_page_fault+0x175/0x180
[ 4632.225738]  ? asm_exc_page_fault+0x26/0x30
[ 4632.225741]  ? __pfx_vfs_caches_init+0x10/0x10
[ 4632.225743]  ? __pfx_vfs_caches_init+0x10/0x10
[ 4632.225745]  ? __pfx_vfs_caches_init+0x10/0x10
[ 4632.225746]  ? arch_adjust_kprobe_addr+0x9/0x60
[ 4632.225748]  _kprobe_addr+0x66/0x90
[ 4632.225752]  register_kprobe+0x44/0x690
[ 4632.225755]  stapkp_register_probe+0x124/0x180
[stap_7d90e889b82f98d2135859abdd7b9927_53381]
[ 4632.225763]  _stp_ctl_write_cmd+0x1069/0x2150
[stap_7d90e889b82f98d2135859abdd7b9927_53381]
[ 4632.225772]  ? inode_security+0x22/0x60
[ 4632.225775]  proc_reg_write+0x5a/0xa0
[ 4632.225777]  vfs_write+0xef/0x400
[ 4632.225779]  ? __do_sys_clone3+0xe0/0x120
[ 4632.225782]  ? __fget_light+0x85/0x100
[ 4632.225785]  ksys_write+0x6f/0xf0
[ 4632.225788]  do_syscall_64+0x61/0xe0
[ 4632.225790]  ? syscall_exit_to_user_mode+0x22/0x40
[ 4632.225792]  ? do_syscall_64+0x70/0xe0
[ 4632.225794]  ? syscall_exit_to_user_mode+0x22/0x40
[ 4632.225796]  ? do_syscall_64+0x70/0xe0
[ 4632.225798]  ? count_memcg_events.constprop.0+0x1a/0x30
[ 4632.225801]  ? handle_mm_fault+0xa2/0x360
[ 4632.225803]  ? do_user_addr_fault+0x204/0x670
[ 4632.225806]  ? exc_page_fault+0x7f/0x180
[ 4632.225808]  entry_SYSCALL_64_after_hwframe+0x6e/0x76
[ 4632.225810] RIP: 0033:0x7f9040b37ccd
[ 4632.225829] Code: e5 48 83 ec 20 48 89 55 e8 48 89 75 f0 89 7d f8 e8 58 1d
f8 ff 48 8b 55 e8 48 8b 75 f0 41 89 c0 8b 7d f8 b8 01 00 00 00 0f 05 <48> 3d 00
f0 ff ff 77 33 44 89 c7 48 89 45 f8 e8 af 1d f8 ff 48 8b
[ 4632.225831] RSP: 002b:00007ffe3ffa0140 EFLAGS: 00000293 ORIG_RAX:
0000000000000001
[ 4632.225833] RAX: ffffffffffffffda RBX: 0000000000000008 RCX:
00007f9040b37ccd
[ 4632.225834] RDX: 000000000000000c RSI: 00007ffe3ffa0170 RDI:
0000000000000004
[ 4632.225835] RBP: 00007ffe3ffa0160 R08: 0000000000000000 R09:
00007ffe3ff9f2e7
[ 4632.225836] R10: 0000000000000008 R11: 0000000000000293 R12:
0000000000000008
[ 4632.225837] R13: 00007ffe3ffa2878 R14: 0000000000008002 R15:
00007ffe3ffa06c4
[ 4632.225840]  </TASK>
[ 4632.225841] Modules linked in:
stap_7d90e889b82f98d2135859abdd7b9927_53381(OE) uinput rfcomm snd_seq_dummy
snd_hrtimer xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp
nf_conntrack_tftp bridge stp llc nf_conntrack_netbios_ns nf_conntrack_broadcast
nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4
nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_tables ebtable_nat
ebtable_broute ip6table_nat ip6table_mangle ip6table_raw ip6table_security
iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle
iptable_raw iptable_security ip_set nfnetlink ebtable_filter ebtables
ip6table_filter iptable_filter qrtr bnep sunrpc binfmt_misc snd_soc_avs
snd_soc_hda_codec snd_hda_ext_core snd_soc_core snd_compress ac97_bus
snd_pcm_dmaengine uvcvideo btusb btrtl btintel uvc btbcm videobuf2_vmalloc
btmtk videobuf2_memops videobuf2_v4l2 bluetooth videobuf2_common videodev mc
iwlmvm mac80211 intel_rapl_msr intel_rapl_common intel_tcc_cooling
snd_hda_codec_hdmi x86_pkg_temp_thermal
[ 4632.225877]  intel_powerclamp coretemp mei_pxp iTCO_wdt mei_hdcp libarc4
snd_ctl_led kvm_intel mei_wdt intel_pmc_bxt iTCO_vendor_support
snd_hda_codec_realtek ee1004 snd_hda_codec_generic kvm irqbypass rapl iwlwifi
snd_hda_intel intel_cstate snd_intel_dspcfg intel_uncore think_lmi
snd_intel_sdw_acpi vfat wmi_bmof fat firmware_attributes_class cfg80211
snd_hda_codec snd_seq intel_wmi_thunderbolt snd_hda_core pcspkr i2c_i801 mei_me
snd_hwdep snd_seq_device i2c_smbus snd_pcm thinkpad_acpi idma64 mei snd_timer
ledtrig_audio ie31200_edac platform_profile intel_pch_thermal rfkill snd
soundcore acpi_pad joydev loop zram dm_crypt i915 nouveau crct10dif_pclmul
crc32_pclmul crc32c_intel polyval_clmulni polyval_generic rtsx_pci_sdmmc
ghash_clmulni_intel mmc_core nvme drm_ttm_helper sha512_ssse3 drm_exec
drm_gpuvm gpu_sched mxm_wmi i2c_algo_bit drm_buddy ttm sha256_ssse3 nvme_core
drm_display_helper e1000e rtsx_pci sha1_ssse3 nvme_auth cec i2c_hid_acpi
i2c_hid video pinctrl_sunrisepoint wmi serio_raw scsi_dh_rdac scsi_dh_emc
[ 4632.225919]  scsi_dh_alua ip6_tables ip_tables dm_multipath fuse
[ 4632.225924] CR2: ffffffffbad48280
[ 4632.225925] ---[ end trace 0000000000000000 ]---
[ 4632.225926] RIP: 0010:arch_adjust_kprobe_addr+0x9/0x60
[ 4632.225928] Code: cc cc cc 48 89 de 48 89 ef 5b 5d e9 f1 f8 ff ff 90 90 90
90 90 90 90 90 90 90 90 90 90 90 90 90 90 66 0f 1f 00 0f 1f 44 00 00 <8b> 07 3d
66 0f 1f 00 74 24 25 ff ff ff fe 41 b8 0c f0 e1 05 41 f7
[ 4632.225930] RSP: 0018:ffffc26e47b67c38 EFLAGS: 00010282
[ 4632.225931] RAX: 0000000000000001 RBX: ffffffffbad48280 RCX:
ffffffffbad48280
[ 4632.225932] RDX: ffffc26e47b67c6f RSI: 0000000000000000 RDI:
ffffffffbad48280
[ 4632.225933] RBP: ffffc26e47b67c6f R08: fffffffffd2b7d7f R09:
ffffc26e47b67c40
[ 4632.225934] R10: 0000000000000000 R11: 0000000000033a98 R12:
0000000000000000
[ 4632.225935] R13: 0000000000000000 R14: 0000000000000000 R15:
ffffffffc1f40db0
[ 4632.225936] FS:  00007f9040a2e140(0000) GS:ffff9fcc8f9c0000(0000)
knlGS:0000000000000000
[ 4632.225938] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 4632.225939] CR2: ffffffffbad48280 CR3: 000000024e98e001 CR4:
00000000003706f0
[ 4632.225940] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[ 4632.225941] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[ 4632.225943] note: stapio[53381] exited with irqs disabled

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

--- Comment #5 from William Cohen <wcohen at redhat dot com> ---
On the machine that observed the problem poll_map.exp is using -g to compile
poll_map.stp. poll_map.stp uses 'kernel.function("vfs_*").call' insert kprobes.
With -g mode one of the probe points it attempts to instrument is
'kernel.function("vfs_caches_init").call'.  This is an initialization function
on a page that is freed up after initialization.  This problem appears to occur
on one particular machine.  I suspect that it might happening on other machines
for other for tests/functions.  It might be helpful to look to see if anything
in /proc/kallsyms match up with the lower 24-bits of ffffffffa64a65c0 (4a65c0)
on the machine that the problem initially occurred on:

sudo cat /proc/kallsyms |grep 4a65c0

Then take a look to see if any of those functions have and __init in front of
the of them using the function lookup on
https://elixir.bootlin.com/linux/v6.8.1/source.

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

--- Comment #6 from William Cohen <wcohen at redhat dot com> ---
Installed kernel-debug-6.9.0-0.rc0.20240314git480e035fc4c7.5.fc41.x86_64 and
did the search through /proc/kallsyms mentioned in the previous comment.

$ sudo cat /proc/kallsyms |grep 4a65c0
ffffffffb84a65c0 T vfs_caches_init

It looks like might be poll_map.exp that is tripping tripping things up for
this PR.  Just checked in the following git commit.  Check to see if this
addresses some of the problem.  There might still be other -g use with wildcard
probes that cause problems.

commit eb760b0d09d8170988add7f2052ff6e40a747304 (HEAD -> master, origin/master,
origin/HEAD)
Author: William Cohen <wcohen@redhat.com>
Date:   Wed Mar 20 10:24:53 2024 -0400

    Remove unneeded guru mode option from poll_map.exp

    Guru mode should only be used when it is really needed to allow the
    systemtap script change program state or disable some safety check or
    black list exclusions. With guru mode enabled on a particular machine
    this test would attempt to probe
    kernel.function("vfs_caches_init").call, an initialization function on
    a page that would would later freed.  The script would get page fault
    when attempting to install the kprobe for this function.

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

--- Comment #7 from William Cohen <wcohen at redhat dot com> ---
I did some more looking around to see where the session's guru_mode would
affect the list of points blocked.  The following URL points at a line that
mentions PR6503, work to allow probing function in the init/exit sections of a
module.  If the probe is on kernel code the init/exit sections are blocked:

https://sourceware.org/git/?p=systemtap.git;a=blob;f=dwflpp.cxx;h=26e9144cdcc7083581aeff3e101044b5542f43d8;hb=HEAD#l4519

However, the test for guru_mode ignores that and sets the blocklisted to 
dwflpp::blocklisted_none allowing problematic probe in kernels init to be
probed:

https://sourceware.org/git/?p=systemtap.git;a=blob;f=dwflpp.cxx;h=26e9144cdcc7083581aeff3e101044b5542f43d8;hb=HEAD#l4543

Maybe the following line:

if (sess.guru_mode)

should be:

if (sess.guru_mode && module != TOK_KERNEL)

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

--- Comment #8 from William Cohen <wcohen at redhat dot com> ---
Created attachment 15425
  --> https://sourceware.org/bugzilla/attachment.cgi?id=15425&action=edit
Proposed patch to prevent guru probing of kernel __init and __kprobe functions

The kernel init function run when the kernel starts up and then the pages they
are on may be freed and used for other purposes.  It doesn't make sense to
allow them to be probed. At best they will never get hit. At worst the page
they are on may not be mapped in and attempting to register a kprobe on the
nonexistent page will cause page faults that can't be handled. Similarly, It is
unwise to allow kprobes on functions that are marked unsafe for kprobes.  This
attempts to probe those problem areas are only made when guru mode is used. 
This patch prevents guru mode from attempting to probe those problem areas.

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

--- Comment #9 from William Cohen <wcohen at redhat dot com> ---
I ran a "make installcheck" with this patch on the machine that reported
unhandled page faults for kprobe registration when running "make installcheck".
 The tests ran to completion with the patch.

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

[Bug runtime/31500] stapio exited with irqs disabled

[wcohen at redhat dot com]

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

William Cohen <wcohen at redhat dot com> changed:

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

--- Comment #10 from William Cohen <wcohen at redhat dot com> ---
This issue should be addressed by the following patch:

commit 7cc8f31116c5bf218572f88080f3009e5c474a0f (HEAD -> master, origin/master,
origin/HEAD)
Author: William Cohen <wcohen@redhat.com>
Date:   Fri Mar 22 10:29:49 2024 -0400

    PR31500: Never allow probing of kernel __init or __kprobes functions

    When guru mode was used it was possble to get systemtap to instrument
    kernel functions marked with __init or __kprobes.  By the time that
    systemtap instrumentation is being loaded a kernel __init marked
    functions has already run and may be in a section of memory that has
    been freed up.  At best this probe will never trigger.  At worst the
    registration of the probe will cause a memory fault causing the
    process to be killed.  Also probes shouldn't be allowed on __kprobes
    functions as a rule.

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