search

Tert-butyllithium / syscord

A syscall hooker/capturer with low overhead, inspired by sysdig
MIT License
3 stars 5 forks source link

`hashtable_put ` crash in testing Unixbench #13

Closed holaymzhang closed 3 years ago

holaymzhang commented 3 years ago

[ 9886.935561] my_sysdig: loading out-of-tree module taints kernel. [ 9887.022469] [my_sysdig:] These following syscalls have been special handled [ 9887.022489] [my_sysdig:] 17:getcwd - getcwd_handle+0x0/0xa0 [my_sysdig] [ 9887.029480] [my_sysdig:] 22:epoll_pwait - epoll_pwait_handle+0x0/0x14 [my_sysdig] [ 9887.036120] [my_sysdig:] 23:dup - dup_handle+0x0/0x5c [my_sysdig] [ 9887.043634] [my_sysdig:] 29:ioctl - ioctl_handle+0x0/0x60 [my_sysdig] [ 9887.049760] [my_sysdig:] 56:openat - openat_handle+0x0/0xc0 [my_sysdig] [ 9887.056222] [my_sysdig:] 57:close - close_handle+0x0/0x54 [my_sysdig] [ 9887.062864] [my_sysdig:] 62:lseek - lseek_handle+0x0/0x60 [my_sysdig] [ 9887.069326] [my_sysdig:] 63:read - read_handle+0x0/0xe4 [my_sysdig] [ 9887.075789] [my_sysdig:] 66:writev - writev_handle+0x0/0x84 [my_sysdig] [ 9887.082096] [my_sysdig:] 80:fstat - fstat_handle+0x0/0x50 [my_sysdig] [ 9887.088751] [my_sysdig:] 94:exit_group - exit_group_handle+0x0/0x50 [my_sysdig] [ 9887.095234] [my_sysdig:] 98:futex - futex_handle+0x0/0x60 [my_sysdig] [ 9887.102569] [my_sysdig:] 101:nanosleep - nanosleep_handle+0x0/0x44 [my_sysdig] [ 9887.109058] [my_sysdig:] 131:tgkill - tgkill_handle+0x0/0x5c [my_sysdig] [ 9887.116325] [my_sysdig:] 174:getuid - getuid_handle+0x0/0x4c [my_sysdig] [ 9887.123066] [my_sysdig:] 198:socket - socket_handle+0x0/0x60 [my_sysdig] [ 9887.129800] [my_sysdig:] 206:sendto - sendto_handle+0x0/0x50 [my_sysdig] [ 9887.136531] [my_sysdig:] 215:munmap - munmap_handle+0x0/0x54 [my_sysdig] [ 9887.143264] [my_sysdig:] 220:clone - clone_handle+0x0/0x50 [my_sysdig] [ 9887.149988] [my_sysdig:] 222:mmap - mmap_handle+0x0/0x4c [my_sysdig] [ 9887.156747] [my_sysdig:] pid=0 and proc_name=Run

root@genericarmv8:~# [ 9887.163121] [my_sysdig:] load successfully! [ 9926.525850] systemd-journald[124]: Sent WATCHDOG=1 notification. [10038.861028] systemd-journald[124]: Sent WATCHDOG=1 notification. [10094.543462] systemd-journald[124]: Sent WATCHDOG=1 notification. [10159.817170] Unable to handle kernel paging request at virtual address ffffffc088a4fc8c [10159.825118] Mem abort info: [10159.827927] ESR = 0x96000005 [10159.830993] EC = 0x25: DABT (current EL), IL = 32 bits [10159.836317] SET = 0, FnV = 0 [10159.839377] EA = 0, S1PTW = 0 [10159.842524] Data abort info: [10159.845410] ISV = 0, ISS = 0x00000005 [10159.849245] CM = 0, WnR = 0 [10159.852219] swapper pgtable: 4k pages, 39-bit VAs, pgdp=0000000080cb4000 [10159.858935] [ffffffc088a4fc8c] pgd=0000000000000000, pud=0000000000000000 [10159.865741] Internal error: Oops: 96000005 [#1] PREEMPT SMP [10159.871318] Modules linked in: my_sysdig(O) [10159.875507] CPU: 1 PID: 19405 Comm: Run Tainted: G O 5.4.50 #1 [10159.882649] Hardware name: ARM Juno development board (r2) (DT) [10159.888573] pstate: 00000005 (nzcv daif -PAN -UAO) [10159.893373] pc : hashtable_put+0x70/0x134 [my_sysdig] [10159.898591] lr : syscall_enter_probe+0x88/0xb0 [my_sysdig]

[10159.904079] sp : ffffffc011663d90 [10159.907562] x29: ffffffc011663d90 x28: ffffff896eb0f180 Broadcast mess[a1g0e1 5f9r.o9m1 2878] x27: 0000000000000000 x26: 0000000000000000 systemd-journald@genericarmv8 (Mon 2021-05-03 16:45:43 UTC):

kernel[191]: [10159.865741] Internal error: Oops: 96000005 [#1] PREEMPT SMP

[10159.932981] x25: 0000000056000000 x24: 0000000000000015 [10159.938296] x23: 0000000080000000 x22: 0000000000004bcd [10159.943611] x21: ffffffc011663df0 x20: ffffffc008a4fca0 [10159.948926] x19: ffffffc008a47c88 x18: 0000000000000000 [10159.954241] x17: 0000000000000000 x16: 0000000000000000 [10159.959556] x15: ffffffffffffffff x14: ffffffffff000000 [10159.964871] x13: ffffffffffffffff x12: 0000000000000018 [10159.970186] x11: 0101010101010101 x10: 7f7f7f7f7f7f7f7f [10159.975501] x9 : 7f7f7f7f7f7f7f7f x8 : feff27feff6d7451 [10159.980816] x7 : 000000ffffffffff x6 : 0000290000000000 [10159.986131] x5 : 0000007f84046130 x4 : 0000007f00000063 [10159.991446] x3 : 0000000080008000 x2 : ffffffc011663df0 [10159.996761] x1 : 0000000000004bcd x0 : ffffffc088a4fc88 [10160.002075] Call trace: [10160.004521] hashtable_put+0x70/0x134 [my_sysdig] [10160.009228] syscall_enter_probe+0x88/0xb0 [my_sysdig] [10160.014377] syscall_trace_enter+0x128/0x208 [10160.018649] el0_svc_common.constprop.0+0x154/0x168 [10160.023530] el0_svc_handler+0x80/0xa0 [10160.027278] el0_svc+0x8/0xc [10160.030159] Code: b8636a63 34000123 937b7c63 8b030260 (b9400400) [10160.036258] ---[ end trace c2c2e148a32cb8c4 ]--- [10160.040893] note: Run[19405] exited with preempt_count 2

Broadcast message from systemd-journald@genericarmv8 (Mon 2021-05-03 16:45:44 UTC):

kernel[191]: [10160.030159] Code: b8636a63 34000123 937b7c63 8b030260 (b9400400)

[10180.820775] rcu: INFO: rcu_preempt self-detected stall on CPU [10180.826555] rcu: 4-....: (5249 ticks this GP) idle=dce/1/0x4000000000000002 softirq=423563/423563 fqs=2625 [10180.836407] (t=5253 jiffies g=1123205 q=1014) [10180.840859] Task dump for CPU 4: [10180.844093] Run R running task 0 19404 19163 0x00000602 [10180.851164] Call trace: [10180.853626] dump_backtrace+0x0/0x148 [10180.857299] show_stack+0x24/0x30 [10180.860628] sched_show_task+0x118/0x140 [10180.864564] dump_cpu_task+0x48/0x58 [10180.868152] rcu_dump_cpu_stacks+0x9c/0xd8 [10180.872262] rcu_sched_clock_irq+0x934/0xba0 [10180.876546] update_process_times+0x34/0x70 [10180.880741] tick_sched_handle.isra.0+0x44/0x68 [10180.885283] tick_sched_timer+0x50/0xa0 [10180.889131] __hrtimer_run_queues+0x164/0x3d8 [10180.893502] hrtimer_interrupt+0xec/0x248 [10180.897527] arch_timer_handler_phys+0x3c/0x50 [10180.901985] handle_percpu_devid_irq+0xa4/0x2b8 [10180.906531] generic_handle_irq+0x34/0x50 [10180.910553] __handle_domain_irq+0x6c/0xc0 [10180.914661] gic_handle_irq+0x64/0xc0 [10180.918333] el1_irq+0xb8/0x180 [10180.921483] queued_spin_lock_slowpath+0xa0/0x318 [10180.926203] _raw_spin_lock+0x60/0x70 [10180.929884] syscall_enter_probe+0x58/0xb0 [my_sysdig] [10180.935040] syscall_trace_enter+0x128/0x208 [10180.939325] el0_svc_common.constprop.0+0x154/0x168 [10180.944217] el0_svc_handler+0x80/0xa0 [10180.947976] el0_svc+0x8/0xc

root@genericarmv8:~# root@genericarmv8:~# root@genericarmv8:~# root@genericarmv8:~# root@genericarmv8:~# [10192.142334] systemd-journald[124]: Sent WATCHDOG=1 notification. [10243.831292] rcu: INFO: rcu_preempt self-detected stall on CPU [10243.837071] rcu: 4-....: (20971 ticks this GP) idle=dce/1/0x4000000000000002 softirq=423563/423563 fqs=9823 [10243.847009] (t=21006 jiffies g=1123205 q=2266) [10243.851548] Task dump for CPU 4: [10243.854782] Run R running task 0 19404 19163 0x00000602 [10243.861854] Call trace: [10243.864313] dump_backtrace+0x0/0x148 [10243.867985] show_stack+0x24/0x30 [10243.871313] sched_show_task+0x118/0x140 [10243.875249] dump_cpu_task+0x48/0x58 [10243.878836] rcu_dump_cpu_stacks+0x9c/0xd8 [10243.882945] rcu_sched_clock_irq+0x934/0xba0 [10243.887228] update_process_times+0x34/0x70 [10243.891424] tick_sched_handle.isra.0+0x44/0x68 [10243.895965] tick_sched_timer+0x50/0xa0 [10243.899813] hrtimer_run_queues+0x164/0x3d8 [10243.904183] hrtimer_interrupt+0xec/0x248 [10243.908207] arch_timer_handler_phys+0x3c/0x50 [10243.912665] handle_percpu_devid_irq+0xa4/0x2b8 [10243.917210] generic_handle_irq+0x34/0x50 [10243.921233] handle_domain_irq+0x6c/0xc0 [10243.925340] gic_handle_irq+0x64/0xc0 [10243.929011] el1_irq+0xb8/0x180 [10243.932161] queued_spin_lock_slowpath+0xa0/0x318 [10243.936881] _raw_spin_lock+0x60/0x70 [10243.940561] syscall_enter_probe+0x58/0xb0 [my_sysdig] [10243.945718] syscall_trace_enter+0x128/0x208 [10243.950003] el0_svc_common.constprop.0+0x154/0x168 [10243.954896] el0_svc_handler+0x80/0xa0 [10243.958654] el0_svc+0x8/0xc [10298.854947] systemd-journald[124]: Sent WATCHDOG=1 notification. [10306.841808] rcu: INFO: rcu_preempt self-detected stall on CPU [10306.847582] rcu: 4-....: (36693 ticks this GP) idle=dce/1/0x4000000000000002 softirq=423563/423563 fqs=15682 [10306.857607] (t=36758 jiffies g=1123205 q=3358) [10306.862147] Task dump for CPU 4: [10306.865380] Run R running task 0 19404 19163 0x00000602 [10306.872450] Call trace: [10306.874905] dump_backtrace+0x0/0x148 [10306.878577] show_stack+0x24/0x30 [10306.881905] sched_show_task+0x118/0x140 [10306.885840] dump_cpu_task+0x48/0x58 [10306.889427] rcu_dump_cpu_stacks+0x9c/0xd8 [10306.893536] rcu_sched_clock_irq+0x934/0xba0 [10306.897818] update_process_times+0x34/0x70 [10306.902013] tick_sched_handle.isra.0+0x44/0x68 [10306.906554] tick_sched_timer+0x50/0xa0 [10306.910402] hrtimer_run_queues+0x164/0x3d8 [10306.914772] hrtimer_interrupt+0xec/0x248 [10306.918795] arch_timer_handler_phys+0x3c/0x50 [10306.923252] handle_percpu_devid_irq+0xa4/0x2b8 [10306.927797] generic_handle_irq+0x34/0x50 [10306.931820] handle_domain_irq+0x6c/0xc0 [10306.935927] gic_handle_irq+0x64/0xc0 [10306.939598] el1_irq+0xb8/0x180 [10306.942748] queued_spin_lock_slowpath+0xa0/0x318 [10306.947466] _raw_spin_lock+0x60/0x70 [10306.951144] syscall_enter_probe+0x58/0xb0 [my_sysdig] [10306.956299] syscall_trace_enter+0x128/0x208 [10306.960583] el0_svc_common.constprop.0+0x154/0x168 [10306.965476] el0_svc_handler+0x80/0xa0 [10306.969235] el0_svc+0x8/0xc [10369.852330] rcu: INFO: rcu_preempt self-detected stall on CPU [10369.858104] rcu: 4-....: (52415 ticks this GP) idle=dce/1/0x4000000000000002 softirq=423563/423563 fqs=22081 [10369.868129] (t=52511 jiffies g=1123205 q=6778) [10369.872668] Task dump for CPU 4: [10369.875902] Run R running task 0 19404 19163 0x00000602 [10369.882972] Call trace: [10369.885428] dump_backtrace+0x0/0x148 [10369.889100] show_stack+0x24/0x30 [10369.892429] sched_show_task+0x118/0x140 [10369.896363] dump_cpu_task+0x48/0x58 [10369.899951] rcu_dump_cpu_stacks+0x9c/0xd8 [10369.904059] rcu_sched_clock_irq+0x934/0xba0 [10369.908343] update_process_times+0x34/0x70 [10369.912537] tick_sched_handle.isra.0+0x44/0x68 [10369.917078] tick_sched_timer+0x50/0xa0 [10369.920927] hrtimer_run_queues+0x164/0x3d8 [10369.925297] hrtimer_interrupt+0xec/0x248 [10369.929320] arch_timer_handler_phys+0x3c/0x50 [10369.933777] handle_percpu_devid_irq+0xa4/0x2b8 [10369.938322] generic_handle_irq+0x34/0x50 [10369.942344] handle_domain_irq+0x6c/0xc0 [10369.946451] gic_handle_irq+0x64/0xc0 [10369.950122] el1_irq+0xb8/0x180 [10369.953271] queued_spin_lock_slowpath+0xa0/0x318 [10369.957990] _raw_spin_lock+0x60/0x70 [10369.961669] syscall_enter_probe+0x58/0xb0 [my_sysdig] [10369.966825] syscall_trace_enter+0x128/0x208 [10369.971110] el0_svc_common.constprop.0+0x154/0x168 [10369.976003] el0_svc_handler+0x80/0xa0 [10369.979761] el0_svc+0x8/0xc [10369.985505] systemd-journald[124]: Sent WATCHDOG=1 notification. [10406.386270] statistics: 11379 [10406.389290] saving to file...with length: 321368 [10406.389421] it is time to dump records to file with offset: 0/321368, current stat: 11379 [10432.862855] rcu: INFO: rcu_preempt self-detected stall on CPU [10432.876818] rcu: 4-....: (68137 ticks this GP) idle=dce/1/0x4000000000000002 softirq=423563/423563 fqs=29433 [10432.886844] (t=68267 jiffies g=1123205 q=7952) [10432.891383] Task dump for CPU 4: [10432.894616] Run R running task 0 19404 19163 0x00000603 [10432.901686] Call trace: [10432.904142] dump_backtrace+0x0/0x148 [10432.907815] show_stack+0x24/0x30 [10432.911143] sched_show_task+0x118/0x140 [10432.915079] dump_cpu_task+0x48/0x58 [10432.918666] rcu_dump_cpu_stacks+0x9c/0xd8 [10432.922775] rcu_sched_clock_irq+0x934/0xba0 [10432.927058] update_process_times+0x34/0x70 [10432.931252] tick_sched_handle.isra.0+0x44/0x68 [10432.935794] tick_sched_timer+0x50/0xa0 [10432.939642] hrtimer_run_queues+0x164/0x3d8 [10432.944012] hrtimer_interrupt+0xec/0x248 [10432.948035] arch_timer_handler_phys+0x3c/0x50 [10432.952492] handle_percpu_devid_irq+0xa4/0x2b8 [10432.957037] generic_handle_irq+0x34/0x50 [10432.961060] handle_domain_irq+0x6c/0xc0 [10432.965166] gic_handle_irq+0x64/0xc0 [10432.968837] el1_irq+0xb8/0x180 [10432.971987] queued_spin_lock_slowpath+0xa0/0x318 [10432.976705] _raw_spin_lock+0x60/0x70 [10432.980386] syscall_enter_probe+0x58/0xb0 [my_sysdig] [10432.985540] syscall_trace_enter+0x128/0x208 [10432.989824] el0_svc_common.constprop.0+0x154/0x168 [10432.994717] el0_svc_handler+0x80/0xa0 [10432.998475] el0_svc+0x8/0xc

Tert-butyllithium commented 3 years ago

We have updated the hashtable_lock form spin_lock_irq to spin_lock... we will rollback and test it..