From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 62193 invoked by alias); 22 Jan 2019 09:51:47 -0000 Mailing-List: contact systemtap-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Post: List-Help: , Sender: systemtap-owner@sourceware.org Received: (qmail 62132 invoked by uid 48); 22 Jan 2019 09:51:41 -0000 From: "leisurelysw24 at gmail dot com" To: systemtap@sourceware.org Subject: [Bug uprobes/24117] New: System crashes when probing a shared library Date: Tue, 22 Jan 2019 09:51:00 -0000 X-Bugzilla-Reason: AssignedTo X-Bugzilla-Type: new X-Bugzilla-Watch-Reason: None X-Bugzilla-Product: systemtap X-Bugzilla-Component: uprobes X-Bugzilla-Version: unspecified X-Bugzilla-Keywords: X-Bugzilla-Severity: normal X-Bugzilla-Who: leisurelysw24 at gmail dot com X-Bugzilla-Status: UNCONFIRMED X-Bugzilla-Resolution: X-Bugzilla-Priority: P2 X-Bugzilla-Assigned-To: systemtap at sourceware dot org X-Bugzilla-Target-Milestone: --- X-Bugzilla-Flags: X-Bugzilla-Changed-Fields: bug_id short_desc product version bug_status bug_severity priority component assigned_to reporter target_milestone Message-ID: Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: http://sourceware.org/bugzilla/ Auto-Submitted: auto-generated MIME-Version: 1.0 X-SW-Source: 2019-q1/txt/msg00011.txt.bz2 https://sourceware.org/bugzilla/show_bug.cgi?id=3D24117 Bug ID: 24117 Summary: System crashes when probing a shared library Product: systemtap Version: unspecified Status: UNCONFIRMED Severity: normal Priority: P2 Component: uprobes Assignee: systemtap at sourceware dot org Reporter: leisurelysw24 at gmail dot com Target Milestone: --- Hi, I continuously encountered system crash when probing a shared libary on a customized linux-based system. (However, probbing kernel function is fine.= )=20 The result of systemtap building process is attached below. I've tried systemtap-3.3 and systemtap-4.0 but got almost the same result. Also, the kernel oops logs are also attached. Is there something missing when probbi= ng a library? Since the issue can be steadily re-produced, if there is anything= I could provide further, please let me know, thanks. ####### systemtap building process ####### Systemtap translator/driver (version 4.0/0.173, non-git sources)=20=20=20= =20=20=20=20=20=20=20=20=20=20=20=20 =20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20= =20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20= =20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20= =20=20=20=20 [3199/9558] Copyright (C) 2005-2018 Red Hat, Inc. and others This is free software; see the source for copying conditions. tested kernel versions: 2.6.18 ... 4.19-rc7 enabled features: BOOST_STRING_REF NLS READLINE Created temporary directory "/tmp/stapUMKO8R" Session arch: x86_64 release: 4.14.24 Searched for library macro files: "/usr/local/systemtap/share/systemtap/tapset/linux", found: 6, processed: 6 Searched for library macro files: "/usr/local/systemtap/share/systemtap/tapset", found: 10, processed: 10 Searched: "/usr/local/systemtap/share/systemtap/tapset/linux/x86_64", found: 20, processed: 20 Searched: "/usr/local/systemtap/share/systemtap/tapset/linux", found: 404, processed: 404 Searched: "/usr/local/systemtap/share/systemtap/tapset/x86_64", found: 1, processed: 1 Searched: "/usr/local/systemtap/share/systemtap/tapset", found: 31, process= ed: 31 Pass 1: parsed user script and 472 library scripts using 102832virt/73236res/5240shr/68520data kb, in 450usr/40sys/483real ms. derive-probes (location #0): process.library("/lib/libuLinux_hal.so").function("PD_SMART_Get_ATA_Info") = of keyword at jtest.stp:3:1 probe PD_SMART_Get_ATA_Info@:-1 process=3D/lib/libuLinux_hal.so reloc=3D.dy= namic pc=3D0x4c4b0 Pass 2: analyzed script: 1 probe, 0 functions, 0 embeds, 0 globals using 104812virt/76436res/6328shr/70500data kb, in 10usr/0sys/10real ms. function recursion-analysis: max-nesting 0 non-recursive probe 0 ('process("/lib/libuLinux_hal.so").function("PD_SMART_Get_ATA_Info"= )') locks nothing 1 statements for probe probe_6286 dump_unwindsyms /lib/libuLinux_hal.so index=3D0 base=3D0x10000 Pass 3: translated to C into "/tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122_src.c" using 104952virt/76864res/6648shr/70640data kb, in 20usr/590sys/616real ms. Pass 4: using cached /root/.systemtap/cache/22/stapconf_221407b3fcfafc3ebaef66f97fabc8b0_825.h Running env -uARCH -uKBUILD_EXTMOD -uCROSS_COMPILE -uKBUILD_IMAGE -uKCONFIG_CONFIG -uINSTALL_PATH -uLD_LIBRARY_PATH PATH=3D/usr/bin:/bin:/usr/local/toolchains/bin:/usr/local/sy stemtap/bin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/bin/X11:/usr/local/sbin:/usr= /local/bin make -C /lib/modules/4.14.24/build M=3D/tmp/stapUMKO8R modules CONFIG_DEBUG= _INFO=3D CON FIG_STACK_VALIDATION=3D ARCH=3Dx86_64 --no-print-directory -j9 CC [M] /tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122_src.o CC [M] /tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122_aux_0.o LD [M] /tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122.o Building modules, stage 2. MODPOST 1 modules CC /tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122.mod.o LD [M] /tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122.ko Spawn waitpid result (0x0): 0 /root/.systemtap/cache/58/stap_58f2906e5f7287aa156151822bec2f00_1122.ko Pass 4: compiled C into "stap_58f2906e5f7287aa156151822bec2f00_1122.ko" in 2230usr/1050sys/3005real ms. Cleaning cache, interval reached 357 s > 300 s. Copying /tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122.ko to /root/.systemtap/cache/58/stap_58f2906e5f7287aa156151822bec2f00_1122.ko Copying /tmp/stapUMKO8R/stap_58f2906e5f7287aa156151822bec2f00_1122_src.c to /root/.systemtap/cache/58/stap_58f2906e5f7287aa156151822bec2f00_1122.c Copying /tmp/stapUMKO8R/stapconf_221407b3fcfafc3ebaef66f97fabc8b0_825.h to /root/.systemtap/cache/22/stapconf_221407b3fcfafc3ebaef66f97fabc8b0_825.h Running rm -rf /tmp/stapUMKO8R Spawn waitpid result (0x0): 0 Removed temporary directory "/tmp/stapUMKO8R" ####### kernel oops trace ####### <7>[21149.354183] stap_58f2906e5f7287aa156151822bec2f0_32740 (jtest.stp): systemtap: 4.0/0.173, base: ffffffffa06c6000, memory: 128data/48text/4ctx/2063net/131alloc kb, probes: 1 <4>[21149.366399]=20 <4>[21149.366402] =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D <4>[21149.366403] WARNING: inconsistent lock state <4>[21149.366405] 4.14.24 #1 Tainted: G O=20=20=20 <4>[21149.366406] -------------------------------- <4>[21149.366407] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage. <4>[21149.366409] nmd/9125 [HC0[0]:SC0[0]:HE1:SE1] takes: <4>[21149.366410] ((&(&cmd->abort_work)->timer)){+.?.}, at: [] igrab+0x14/0x50 <4>[21149.366414] {IN-SOFTIRQ-W} state was registered at: <4>[21149.366417] lock_acquire+0xb9/0x200 <4>[21149.366420] call_timer_fn+0x65/0x350 <4>[21149.366421] run_timer_softirq+0x18f/0x5b0 <4>[21149.366424] __do_softirq+0x1d3/0x4cb <4>[21149.366426] irq_exit+0xa0/0xb0 <4>[21149.366428] smp_apic_timer_interrupt+0xa5/0x2d0 <4>[21149.366429] apic_timer_interrupt+0x89/0x90 <4>[21149.366432] cpuidle_enter_state+0xf5/0x320 <4>[21149.366434] do_idle+0x18e/0x1e0 <4>[21149.366436] cpu_startup_entry+0x14/0x20 <4>[21149.366438] start_kernel+0x406/0x40e <4>[21149.366440] secondary_startup_64+0xa5/0xb0 <4>[21149.366441] irq event stamp: 1786871 <4>[21149.366443] hardirqs last enabled at (1786871): [] prepend_path+0x1af/0x590 <4>[21149.366444] hardirqs last disabled at (1786870): [] prepend_path+0x15c/0x590 <4>[21149.366446] softirqs last enabled at (1785922): [] __do_softirq+0x3ba/0x4cb <4>[21149.366448] softirqs last disabled at (1785905): [] irq_exit+0xa0/0xb0 <4>[21149.366449]=20 <4>[21149.366449] other info that might help us debug this: <4>[21149.366450] Possible unsafe locking scenario: <4>[21149.366450]=20 <4>[21149.366451] CPU0 <4>[21149.366452] ---- <4>[21149.366453] lock((&(&cmd->abort_work)->timer)); <4>[21149.366454] <4>[21149.366455] lock((&(&cmd->abort_work)->timer)); <4>[21149.366457]=20 <4>[21149.366457] *** DEADLOCK *** <4>[21149.366457]=20 <4>[21149.366458] 1 lock held by nmd/9125: <4>[21149.366459] #0: (&ut->inode_lock){+.+.}, at: [] stapiu_mmap_found+0x107/0x470 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366464]=20 <4>[21149.366464] stack backtrace: <4>[21149.366466] CPU: 2 PID: 9125 Comm: nmd Tainted: G O 4.14= .24 #1 <4>[21149.366467] Hardware name: INSYDE QV99/Type2 - Board Product Name1, B= IOS QV99IR31 07/16/2014 <4>[21149.366468] Call Trace: <4>[21149.366471] dump_stack+0x5e/0x8e <4>[21149.366473] print_usage_bug+0x1e7/0x1f9 <4>[21149.366475] mark_lock+0x513/0x5d0 <4>[21149.366477] __lock_acquire+0x3d8/0x19b0 <4>[21149.366480] ? stapiu_mmap_found+0x107/0x470 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366483] ? stapiu_mmap_found+0x107/0x470 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366485] ? lock_acquire+0xb9/0x200 <4>[21149.366487] lock_acquire+0xb9/0x200 <4>[21149.366489] ? igrab+0x14/0x50 <4>[21149.366491] _raw_spin_lock+0x27/0x40 <4>[21149.366492] ? igrab+0x14/0x50 <4>[21149.366494] igrab+0x14/0x50 <4>[21149.366496] stapiu_mmap_found+0x246/0x470 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366498] ? lock_acquire+0xb9/0x200 <4>[21149.366501] ? __stp_call_mmap_callbacks.part.71+0x5c/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366503] ? __stp_call_mmap_callbacks_for_task+0x18f/0x230 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366506] ? __stp_tf_quiesce_worker+0x114/0x130 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366508] ? task_work_run+0x74/0xb0 <4>[21149.366510] ? get_signal+0x946/0x970 <4>[21149.366512] ? find_held_lock+0x3f/0xc0 <4>[21149.366514] ? do_signal+0x1e/0x6b0 <4>[21149.366517] ? __stp_tf_get_map_entry+0x96/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366519] ? __stp_tf_get_map_entry+0x96/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366521] ? _raw_read_unlock_irqrestore+0x2d/0x50 <4>[21149.366523] ? __stp_tf_get_map_entry+0x96/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366525] ? __stp_utrace_task_finder_target_syscall_exit+0x4e/0x300 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366528] ? utrace_report_syscall_exit+0xf6/0x100 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366529] ? do_syscall_64+0x24a/0x460 <4>[21149.366531] ? do_syscall_64+0x26f/0x460 <4>[21149.366533] ? entry_SYSCALL_64_after_hwframe+0x42/0xb7 <1>[21149.366538] BUG: unable to handle kernel paging request at 0000000000769418 <1>[21149.366541] IP: queued_spin_lock_slowpath+0xe9/0x180 <6>[21149.366543] PGD 80000007fc89b067 P4D 80000007fc89b067 PUD 7fa38d067 P= MD 8035a8067 PTE 0 <4>[21149.366548] Oops: 0002 [#1] SMP PTI <4>[21149.366550] Modules linked in: stap_58f2906e5f7287aa156151822bec2f0_32740(O) rfcomm iscsi_tcp(O) libiscsi_tcp(O) libiscsi(O) scsi_transport_iscsi(O) fbdisk(O) xt_TCPMSS xt_= LOG ipt_MASQUERADE xt_REDIRECT nf_nat_redirect iptable_nat nf_nat_masquerade_ip= v4 nf_nat_ipv4 nf_nat xt_policy cfg80211 dummy br_netfilter bridge stp bonding xt_mark xt_set ip_set_hash_netiface ip_set_hash_net ip_set xt_connmark 8021q uvcvideo videobuf2_v4l2 videobuf2_vmalloc videobuf2_memops videobuf2_core snd_usb_caiaq snd_usb_audio snd_usbmidi_lib snd_seq_midi snd_rawmidi fnotif= y(O) udf isofs iTCO_wdt kcopy(O) vfio_pci irqbypass vfio_virqfd vfio ipv6 pl2303 usbserial qm2_i2c(O) intel_ips drbd lru_cache flashcache(O) dm_tier_hro_algo dm_thin_pool dm_bio_prison dm_persistent_data hal_netlink(O) k10temp corete= mp ixgbe mdio igb <4>[21149.366588] e1000e mpt3sas scsi_transport_sas raid_class usb_storage xhci_pci xhci_hcd usblp uhci_hcd ehci_pci ehci_hcd <4>[21149.366595] CPU: 2 PID: 9125 Comm: nmd Tainted: G O 4.14= .24 #1 <4>[21149.366597] Hardware name: INSYDE QV99/Type2 - Board Product Name1, B= IOS QV99IR31 07/16/2014 <4>[21149.366598] task: ffff8807f97421c0 task.stack: ffffc90000804000 <4>[21149.366600] RIP: 0010:queued_spin_lock_slowpath+0xe9/0x180 <4>[21149.366602] RSP: 0018:ffffc90000807bf8 EFLAGS: 00010206 <4>[21149.366604] RAX: 0000000000000b29 RBX: ffff88082caa2c78 RCX: ffff88085e2a2a80 <4>[21149.366606] RDX: 0000000000769418 RSI: 000000002caa2c78 RDI: ffff88082caa2c78 <4>[21149.366607] RBP: ffff88082caa2c78 R08: 00000000000c0000 R09: 0000000000000000 <4>[21149.366609] R10: ffffc90000807b90 R11: 0000000000000622 R12: ffff8807f97421c0 <4>[21149.366610] R13: ffffffffa06d7258 R14: ffffffffa06d7198 R15: 0000000000000000 <4>[21149.366612] FS: 00007fb94937f700(0000) GS:ffff88085e280000(0000) knlGS:0000000000000000 <4>[21149.366613] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[21149.366615] CR2: 0000000000769418 CR3: 00000007ff7c4001 CR4: 00000000001606e0 <4>[21149.366616] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 <4>[21149.366618] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 <4>[21149.366619] Call Trace: <4>[21149.366622] do_raw_spin_lock+0x8a/0x90 <4>[21149.366624] igrab+0x14/0x50 <4>[21149.366627] stapiu_mmap_found+0x246/0x470 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366630] ? lock_acquire+0xb9/0x200 <4>[21149.366633] ? __stp_call_mmap_callbacks.part.71+0x5c/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366637] ? __stp_call_mmap_callbacks_for_task+0x18f/0x230 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366640] ? __stp_tf_quiesce_worker+0x114/0x130 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366643] ? task_work_run+0x74/0xb0 <4>[21149.366645] ? get_signal+0x946/0x970 <4>[21149.366647] ? find_held_lock+0x3f/0xc0 <4>[21149.366650] ? do_signal+0x1e/0x6b0 <4>[21149.366653] ? __stp_tf_get_map_entry+0x96/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366656] ? __stp_tf_get_map_entry+0x96/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366658] ? _raw_read_unlock_irqrestore+0x2d/0x50 <4>[21149.366661] ? __stp_tf_get_map_entry+0x96/0xb0 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366664] ? __stp_utrace_task_finder_target_syscall_exit+0x4e/0x300 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366667] ? utrace_report_syscall_exit+0xf6/0x100 [stap_58f2906e5f7287aa156151822bec2f0_32740] <4>[21149.366669] ? do_syscall_64+0x24a/0x460 <4>[21149.366671] ? do_syscall_64+0x26f/0x460 <4>[21149.366674] ? entry_SYSCALL_64_after_hwframe+0x42/0xb7 <4>[21149.366677] Code: c1 e0 10 45 31 c9 85 c0 74 44 48 89 c2 c1 e8 12 48 = c1 ea 0c 83 e8 01 83 e2 30 48 98 48 81 c2 80 2a 02 00 48 03 14 c5 00 55 70 82 = <48> 89 0a 8b 41 08 85 c0 75 09 f3 90 8b 41 08 85 c0 74 f7 4c 8b=20 <1>[21149.366709] RIP: queued_spin_lock_slowpath+0xe9/0x180 RSP: ffffc90000807bf8 <4>[21149.366710] CR2: 0000000000769418 <4>[21149.366713] ---[ end trace aa625e330e554047 ]--- <3>[21149.368642] BUG: sleeping function called from invalid context at ./include/linux/percpu-rwsem.h:34 <3>[21149.368644] in_atomic(): 1, irqs_disabled(): 1, pid: 9125, name: nmd <4>[21149.368646] INFO: lockdep is turned off. <4>[21149.368647] irq event stamp: 1786871 <4>[21149.368650] hardirqs last enabled at (1786871): [] prepend_path+0x1af/0x590 <4>[21149.368652] hardirqs last disabled at (1786870): [] prepend_path+0x15c/0x590 <4>[21149.368654] softirqs last enabled at (1785922): [] __do_softirq+0x3ba/0x4cb <4>[21149.368657] softirqs last disabled at (1785905): [] irq_exit+0xa0/0xb0 <4>[21149.368659] CPU: 2 PID: 9125 Comm: nmd Tainted: G D O 4.14= .24 #1 <4>[21149.368660] Hardware name: INSYDE QV99/Type2 - Board Product Name1, B= IOS QV99IR31 07/16/2014 <4>[21149.368661] Call Trace: <4>[21149.368664] dump_stack+0x5e/0x8e <4>[21149.368667] ___might_sleep+0x21d/0x250 <4>[21149.368669] exit_signals+0x1b/0x210 <4>[21149.368671] do_exit+0xad/0xce0 <4>[21149.368674] ? do_syscall_64+0x26f/0x460 <4>[21149.368677] rewind_stack_do_exit+0x17/0x20 <6>[21149.368694] note: nmd[9125] exited with preempt_count 1 <3>[21149.369396] utrace_free:797 * task_work_cancel() failed for utrace_resume? task ffff8807f97421c0, 9125, nmd, 0x0 0x0 ##### end ####### --=20 You are receiving this mail because: You are the assignee for the bug.