Support swapper process stack_trace?

[qiyeliu]

Currently using stack_trace to obtain the stack of the swapper thread encounters the following problems：
`>>> trace = stack_trace(0)
Traceback (most recent call last):
File "/usr/lib/python3.8/code.py", line 90, in runcode
exec(code, self.locals)
File "", line 1, in
File "/usr/local/lib/python3.8/dist-packages/drgn-0.0.30+unknown-py3.8-linux-x86_64.egg/drgn/init.py", line 288, in stack_trace
return get_default_prog().stack_trace(thread)
LookupError: task not found

`
Is there a way to trace back the swapper on each cpu?

Thanks.

[osandov]

There is a PID 0 for each CPU, so you need to use the idle_task() to specify which one you want. E.g., stack_trace(idle_task(cpu)). I will improve the error message here.

[osandov]

See the CPU mask helpers for iterating over CPUs: https://drgn.readthedocs.io/en/latest/helpers.html#cpu-masks

[qiyeliu]

There is a PID 0 for each CPU, so you need to use the idle_task() to specify which one you want. E.g., stack_trace(idle_task(cpu)). I will improve the error message here.

I still encounter the following problem when using idle_task, which may be related to bad_pc. Is there a way to trace back to the stack before bad_pc?
` 1 [14043056.383837] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000000
2 [14043056.384797] Mem abort info:
3 [14043056.385124] ESR = 0x86000005
4 [14043056.385430] Exception class = IABT (current EL), IL = 32 bits
5 [14043056.386564] SET = 0, FnV = 0
6 [14043056.386878] EA = 0, S1PTW = 0
7 [14043056.387186] user pgtable: 64k pages, 48-bit VAs, pgdp = 00000000369cec62
8 [14043056.387959] [0000000000000000] pgd=0000000000000000, pud=0000000000000000
9 [14043056.388923] Internal error: Oops: 86000005 [#1] SMP
10 [14043056.392612] Process swapper/1 (pid: 0, stack limit = 0x000000008b8d2aac)
11 [14043056.393340] CPU: 1 PID: 0 Comm: swapper/1 Kdump: loaded Tainted: G OE
12 [14043056.395352] pstate: 80c00005 (Nzcv daif +PAN +UAO)
13 [14043056.395912] pc : (null)
14 [14043056.396322] lr : (null)
15 [14043056.396723] sp : ffff8001c1033f50
16 [14043056.397136] x29: 0000000000000000 x28: 0000000000000000
17 [14043056.397745] x27: 0000000000000000 x26: 0000000000000000
18 [14043056.398357] x25: 0000000000000000 x24: 0000000000000000
19 [14043056.398964] x23: 0000000000000000 x22: 0000000000000000
20 [14043056.399583] x21: 0000000000000001 x20: 0000000000000002
21 [14043056.400191] x19: 0000000000000087 x18: 0000000000000000
22 [14043056.400818] x17: 0000000000000000 x16: 0000000000000000
23 [14043056.401426] x15: 0000000000000000 x14: 0000000000000000
24 [14043056.402034] x13: 0000000000000000 x12: fffffffe9c5c18d0
25 [14043056.402653] x11: 0078756e696c6573 x10: 0000000000000b80
26 [14043056.403274] x9 : ffff8001c1033ea0 x8 : ffff8001c0fdd560
27 [14043056.403889] x7 : 033978d713488fc4 x6 : 0000000000000001
28 [14043056.404525] x5 : 00000000ffffffff x4 : 0000000000000001
29 [14043056.405140] x3 : 0000000000000200 x2 : 00008001b61a0000
30 [14043056.405726] x1 : ffff8001cd9b0fc0 x0 : 0000000000000028
31 [14043056.406313] Call trace:
32 [14043056.406617] Code: bad PC value
33 [14043056.406989] SMP: stopping secondary CPUs
34 [14043056.408977] Starting crashdump kernel...
35 [14043056.409368] Bye!
36 crash> bt
37 PID: 0 TASK: ffff8001c0fdc980 CPU: 1 COMMAND: "swapper/1"
38 #0 [ffff8001c10339a0] machine_kexec at ffff0000480a2eec
39 #1 [ffff8001c1033a00] __crash_kexec at ffff0000481aff00
40 #2 [ffff8001c1033b70] crash_kexec at ffff0000481b0008
41 #3 [ffff8001c1033ba0] die at ffff00004808f744
42 #4 [ffff8001c1033be0] die_kernel_fault at ffff0000480aa9b4
43 #5 [ffff8001c1033c10] __do_kernel_fault at ffff0000480aa684
44 #6 [ffff8001c1033c40] do_page_fault at ffff000048bee47c
45 #7 [ffff8001c1033d30] do_translation_fault at ffff000048bee974
46 #8 [ffff8001c1033d60] do_mem_abort at ffff000048081284
47 #9 [ffff8001c1033f40] el1_ia at ffff00004808310c
48 crash>

`

stack_trace(idle_task(1))
#0 0x0
stack_trace(idle_task(0))
#0 arch_cpu_idle (arch/arm64/kernel/process.c:191)
#1 default_idle_call (kernel/sched/idle.c:93)
#2 cpuidle_idle_call (kernel/sched/idle.c:153)
#3 do_idle (kernel/sched/idle.c:263)
#4 cpu_startup_entry (kernel/sched/idle.c:369)
#5 rest_init (init/main.c:443)
#6 start_kernel (init/main.c:739)

The actual requirement is to look at the input parameters and local variables of each layer of the stack

Thanks.

[osandov]

Ah, it looks like we need an ARM64 version of 412ce95. I can give you a workaround tomorrow once I refresh my memory on the ARM64 calling convention.

[osandov]

I just pushed a commit, 4a3ae32, that should fix this. If you're able to build drgn from source, please try it out.

If you can't build drgn from source, you can use this script as a workaround: https://github.com/osandov/drgn/blob/main/contrib/stack_trace_call_fault.py. Save it somewhere, then from the drgn REPL, call execscript("path/to/stack_trace_call_fault.py"). That should print out the fixed stack trace and also define the trace variable for you to inspect further.

Please let me know if either of these solutions work for you, and feel free to reopen if not.

[qiyeliu]

I just pushed a commit, 4a3ae32, that should fix this. If you're able to build drgn from source, please try it out.

If you can't build drgn from source, you can use this script as a workaround: https://github.com/osandov/drgn/blob/main/contrib/stack_trace_call_fault.py. Save it somewhere, then from the drgn REPL, call execscript("path/to/stack_trace_call_fault.py"). That should print out the fixed stack trace and also define the trace variable for you to inspect further.

Please let me know if either of these solutions work for you, and feel free to reopen if not.

Rebuild drgn from source(drgn-4a3ae326f4855462d38b0c30c1c1f77f7ce4342e) and install it. Execute 'python3 -m drgn -c vmcore3 -s vmlinux' and encounter the following problem. I tried master and had the same problem. Prior to this, the drgn version was drgn-0.0.30 works.

`$ python3 -m drgn -c vmcore -s vmlinux
drgn 0.0.30+unknown (using Python 3.8.10, elfutils 0.176, with libkdumpfile)
warning: can't find loaded modules without kernel debug info
warning: missing debugging symbols for kernel
warning: provided file vmlinux did not match any loaded modules; ignoring
warning: missing some debugging symbols; see https://drgn.readthedocs.io/en/latest/getting_debugging_symbols.html
For help, type help(drgn).

import drgn
from drgn import FaultError, NULL, Object, alignof, cast, container_of, execscript, implicit_convert, offsetof, reinterpret, sizeof, stack_trace
from drgn.helpers.common import *
from drgn.helpers.linux import *

`

Use https://github.com/osandov/drgn/blob/main/contrib/stack_trace_call_fault.py directly.
`>>> stack_trace(idle_task(1))
#0 0x0

stack_trace(idle_task(0))
#0 arch_cpu_idle (arch/arm64/kernel/process.c:191)
#1 default_idle_call (kernel/sched/idle.c:93)
#2 cpuidle_idle_call (kernel/sched/idle.c:153)
#3 do_idle (kernel/sched/idle.c:263)
#4 cpu_startup_entry (kernel/sched/idle.c:369)
#5 rest_init (init/main.c:443)
#6 start_kernel (init/main.c:739)
execscript('stack_trace_call_fault.py')
#0 0xfffffffffffffffc
stack_trace(idle_task(1))
#0 0x0

`
Maybe the first pc was bad.

Another vmcore.

`>>> execscript('stack_trace_call_fault.py')
#0 0x10000000100fd

stack_trace(idle_task(4))
#0 0x1000000010101

`

[osandov]

Thanks, a couple more questions/requests:

1. On commit 4a3ae32, could you please re-run drgn with --log-level=debug and attach the log output? The warnings sound like your vmlinux doesn't match your vmcore, which 0.0.30 was more permissive about but could lead to unexpected results.
2. Could you please also try the issue462 branch? It's a rebase of the fixes onto 0.0.30. Given the potentially mismatched vmlinux and the failure of stack_trace_call_fault.py, I'm not sure how reliable it will be, but it's worth a try.

[qiyeliu]

Thanks, a couple more questions/requests:

1. On commit 4a3ae32, could you please re-run drgn with --log-level=debug and attach the log output? The warnings sound like your vmlinux doesn't match your vmcore, which 0.0.30 was more permissive about but could lead to unexpected results.
2. Could you please also try the issue462 branch? It's a rebase of the fixes onto 0.0.30. Given the potentially mismatched vmlinux and the failure of stack_trace_call_fault.py, I'm not sure how reliable it will be, but it's worth a try.

Add --log-level=debug

$ python3 -m  drgn -c vmcore3 -s vmlinux --log-level=debug
drgn 0.0.30+unknown (using Python 3.8.10, elfutils 0.176, with libkdumpfile)
debug: loading default debugging symbols
debug: provided file vmlinux build ID 5027ccb822ad5d5d65145f771978ee05ac2a3358
debug: created main module kernel
debug: couldn't find kernel build ID
debug: loading debugging symbols for 1 modules
debug: kernel (no build ID): trying standard paths in ":.debug:/usr/lib/debug" for debug file
debug: /usr/lib/debug/boot/vmlinux-xx.aarch64: No such file or directory
debug: /usr/lib/debug/lib/modules/xx.aarch64/vmlinux: No such file or directory
debug: /usr/lib/debug/lib/modules/xx.aarch64/vmlinux.debug: No such file or directory
debug: /boot/vmlinux-xx.aarch64: No such file or directory
debug: /lib/modules/xx.aarch64/build/vmlinux: No such file or directory
debug: /lib/modules/xx.aarch64/vmlinux: No such file or directory
debug: debugging symbols loaded for 0/1 modules
warning: can't find loaded modules without kernel debug info
warning: missing debugging symbols for kernel
warning: provided file vmlinux did not match any loaded modules; ignoring
warning: missing some debugging symbols; see https://drgn.readthedocs.io/en/latest/getting_debugging_symbols.html
For help, type help(drgn).
>>> import drgn
>>> from drgn import FaultError, NULL, Object, alignof, cast, container_of, execscript, implicit_convert, offsetof, reinterpret, sizeof, stack_trace
>>> from drgn.helpers.common import *
>>> from drgn.helpers.linux import *

Create directories and cp vmlinux files:

sudo mkdir -p /usr/lib/debug/lib/modules/xx.aarch64/
sudo cp vmlinux /usr/lib/debug/lib/modules/xx.aarch64/

It works.

$ python3 -m  drgn -c vmcore3 -s vmlinux
drgn 0.0.30+unknown (using Python 3.8.10, elfutils 0.176, with libkdumpfile)
warning: provided file vmlinux did not match any loaded modules; ignoring
warning: missing debugging symbols for tcp_diag
warning: missing debugging symbols for inet_diag
warning: missing debugging symbols for 8021q
warning: missing debugging symbols for garp
warning: missing debugging symbols for mrp
warning: ... missing 25 more
warning: missing some debugging symbols; see https://drgn.readthedocs.io/en/latest/getting_debugging_symbols.html
For help, type help(drgn).
>>> import drgn
>>> from drgn import FaultError, NULL, Object, alignof, cast, container_of, execscript, implicit_convert, offsetof, reinterpret, sizeof, stack_trace
>>> from drgn.helpers.common import *
>>> from drgn.helpers.linux import *
>>> stack_trace(idle_task(4))
#0  0x1000000010101
>>> stack_trace(idle_task(0))
#0  arch_cpu_idle (arch/arm64/kernel/process.c:191)
#1  default_idle_call (kernel/sched/idle.c:93)
#2  cpuidle_idle_call (kernel/sched/idle.c:153)
#3  do_idle (kernel/sched/idle.c:263)
#4  cpu_startup_entry (kernel/sched/idle.c:369)
#5  rest_init (init/main.c:443)
#6  start_kernel (init/main.c:739)
>>> 
>>> stack_trace(0)
Traceback (most recent call last):
  File "/usr/lib/python3.8/code.py", line 90, in runcode
    exec(code, self.locals)
  File "<console>", line 1, in <module>
  File "/usr/local/lib/python3.8/dist-packages/drgn-0.0.30+unknown-py3.8-linux-x86_64.egg/drgn/__init__.py", line 306, in stack_trace
    return get_default_prog().stack_trace(thread)
LookupError: task not found; use stack_trace(idle_task(cpu)) for PID 0
>>> 

Is there a parameter to specify this path /usr/lib/debug/lib/modules/xx.aarch64/vmlinux ？
Is there a difference between -s vmlinux.

Thanks.

[osandov]

Ok, this line explains it:

debug: couldn't find kernel build ID

In the main branch, drgn uses the build ID to match the -s argument to the core dump, but this core dump doesn't have the build ID saved. I will add a fallback for this, but I'd like to know more about why your core dump doesn't have this. Could you please try the following in drgn:

>>> print(prog['VMCOREINFO'].string_().decode())

And let me know if there's a line beginning with BUILD-ID? Also, what kernel version is this? major.minor is probably enough if you're not able to share the full version string.

Finally, how was this vmcore collected? Was it with kdump, makedumpfile, etc?

[qiyeliu]

Ok, this line explains it:

debug: couldn't find kernel build ID

In the main branch, drgn uses the build ID to match the -s argument to the core dump, but this core dump doesn't have the build ID saved. I will add a fallback for this, but I'd like to know more about why your core dump doesn't have this. Could you please try the following in drgn:

>>> print(prog['VMCOREINFO'].string_().decode())

OSRELEASE=4.19.90.xxx.aarch64 == In fact the version is almost equal to longterm 4.19-y

>>> print(prog['VMCOREINFO'].string_().decode())
OSRELEASE=4.19.90.xxx.aarch64
PAGESIZE=65536
SYMBOL(init_uts_ns)=ffff0000497ef2a8
SYMBOL(node_online_map)=ffff0000497e6a00
SYMBOL(swapper_pg_dir)=ffff000049e00000
SYMBOL(_stext)=ffff000048081000
SYMBOL(vmap_area_list)=ffff0000498449b0
SYMBOL(mem_section)=ffff8001ffffccc0
LENGTH(mem_section)=64
SIZE(mem_section)=16
OFFSET(mem_section.section_mem_map)=0
SIZE(page)=64
SIZE(pglist_data)=12608
SIZE(zone)=1920
SIZE(free_area)=104
SIZE(list_head)=16
SIZE(nodemask_t)=8
OFFSET(page.flags)=0
OFFSET(page._refcount)=52
OFFSET(page.mapping)=24
OFFSET(page.lru)=8
OFFSET(page._mapcount)=48
OFFSET(page.private)=40
OFFSET(page.compound_dtor)=16
OFFSET(page.compound_order)=17
OFFSET(page.compound_head)=8
OFFSET(pglist_data.node_zones)=0
OFFSET(pglist_data.nr_zones)=11936
OFFSET(pglist_data.node_start_pfn)=11944
OFFSET(pglist_data.node_spanned_pages)=11960
OFFSET(pglist_data.node_id)=11968
OFFSET(zone.free_area)=192
OFFSET(zone.vm_stat)=1728
OFFSET(zone.spanned_pages)=96
OFFSET(free_area.free_list)=0
OFFSET(list_head.next)=0
OFFSET(list_head.prev)=8
OFFSET(vmap_area.va_start)=0
OFFSET(vmap_area.list)=48
LENGTH(zone.free_area)=14
SYMBOL(log_buf)=ffff00004980dea0
SYMBOL(log_buf_len)=ffff00004980dea8
SYMBOL(log_first_idx)=ffff000049a3b9bc
SYMBOL(clear_idx)=ffff000049a3b9c8
SYMBOL(log_next_idx)=ffff000049a3b9b8
SIZE(printk_log)=16
OFFSET(printk_log.ts_nsec)=0
OFFSET(printk_log.len)=8
OFFSET(printk_log.text_len)=10
OFFSET(printk_log.dict_len)=12
LENGTH(free_area.free_list)=6
NUMBER(NR_FREE_PAGES)=0
NUMBER(PG_lru)=5
NUMBER(PG_private)=12
NUMBER(PG_swapcache)=9
NUMBER(PG_swapbacked)=18
NUMBER(PG_slab)=8
NUMBER(PG_hwpoison)=21
NUMBER(PG_head_mask)=32768
NUMBER(PAGE_BUDDY_MAPCOUNT_VALUE)=-129
NUMBER(HUGETLB_PAGE_DTOR)=2
NUMBER(VA_BITS)=48
NUMBER(kimage_voffset)=0xffff000008000000
NUMBER(PHYS_OFFSET)=0x40000000
KERNELOFFSET=0
CRASHTIME=1737235032

>>> 

And let me know if there's a line beginning with BUILD-ID? Also, what kernel version is this? major.minor is probably enough if you're not able to share the full version string.

Finally, how was this vmcore collected? Was it with kdump, makedumpfile, etc?

makedumpfile.

[osandov]

Okay, that kernel version was before the build ID was added to the VMCOREINFO, so that's my oversight not handling it. I'll fix that.

In the meantime, were you able to test the issue462 branch? Does that give you usable stack traces? If not, I'd love to see the output of trace[0].registers() for a broken stack trace.

Thank you for your patience!

[qiyeliu]

>>> trace = stack_trace(idle_task(1))
>>> trace
#0  0x0
#1  0xfffffffffffffffc
>>> trace[0].registers()
{'x0': 40, 'x1': 18446603343965654976, 'x2': 140744838479872, 'x3': 512, 'x4': 1, 'x5': 4294967295, 'x6': 1, 'x7': 232349720923115460, 'x8': 18446603343754024288, 'x9': 18446603343754378912, 'x10': 2944, 'x11': 33906114280842611, 'x12': 18446744067742898384, 'x13': 0, 'x14': 0, 'x15': 0, 'x16': 0, 'x17': 0, 'x18': 0, 'x19': 135, 'x20': 2, 'x21': 1, 'x22': 0, 'x23': 0, 'x24': 0, 'x25': 0, 'x26': 0, 'x27': 0, 'x28': 0, 'x29': 0, 'fp': 0, 'x30': 0, 'lr': 0, 'sp': 18446603343754379088, 'pstate': 2160066565}
>>> trace[1].registers()
{'x0': 40, 'x1': 18446603343965654976, 'x2': 140744838479872, 'x3': 512, 'x4': 1, 'x5': 4294967295, 'x6': 1, 'x7': 232349720923115460, 'x8': 18446603343754024288, 'x9': 18446603343754378912, 'x10': 2944, 'x11': 33906114280842611, 'x12': 18446744067742898384, 'x13': 0, 'x14': 0, 'x15': 0, 'x16': 0, 'x17': 0, 'x18': 0, 'x19': 135, 'x20': 2, 'x21': 1, 'x22': 0, 'x23': 0, 'x24': 0, 'x25': 0, 'x26': 0, 'x27': 0, 'x28': 0, 'x29': 0, 'fp': 0, 'sp': 18446603343754379088, 'pstate': 2160066565}
>>> 

How to display in hexadecimal format?

[qiyeliu]

python3 -m drgn -c vmcore3 -s vmlinux

>>> trace = stack_trace(idle_task(4))
>>> trace
#0  0x1000000010101
>>> trace[0].registers()
{'x0': 40, 'x1': 18446603351962677312, 'x2': 140753436082176, 'x3': 512, 'x4': 4, 'x5': 4294967295, 'x6': 4, 'x7': 8252799111227160, 'x8': 18446603351820606304, 'x9': 18446603351821352608, 'x10': 2944, 'x11': 0, 'x12': 0, 'x13': 0, 'x14': 0, 'x15': 0, 'x16': 0, 'x17': 0, 'x18': 0, 'x19': 135, 'x20': 16, 'x21': 4, 'x22': 0, 'x23': 0, 'x24': 0, 'x25': 0, 'x26': 0, 'x27': 0, 'x28': 0, 'x29': 72340172838076673, 'fp': 72340172838076673, 'x30': 281474976776449, 'lr': 281474976776449, 'sp': 18446603351821352784, 'pstate': 2160066565}
>>> trace[1].registers()
Traceback (most recent call last):
  File "/usr/lib/python3.8/code.py", line 90, in runcode
    exec(code, self.locals)
  File "<console>", line 1, in <module>
IndexError: stack frame index out of range
>>> hex(281474976776449,)
'0x1000000010101'
>>> hex(281474976776449)
'0x1000000010101'
>>> 

[osandov]

The interesting thing here is that the link register is garbage in both dumps (0 in the first, 0x1000000010101 in the second). This means we have no idea who called the bad PC. (The dmesg you pasted earlier also showed this, and crash apparently also failed to get a stack trace below the bad PC.) It's possible that something was too badly corrupted, or there is a bug in how 4.19 captures the registers.

This makes it impossible to get a reliable trace automatically. One thing I've done in similar cases before is manually inspecting the contents of stack memory and guessing where the caller was. If you're able to share the vmcore and vmlinux (feel free to email me privately), I could take a look. If not, tomorrow I can try to come up with a script to get you started.

[osandov]

One thing you can check quickly is

print_annotated_memory(trace[0].register("sp"), 4096)

That will dump the contents of the stack below the stack pointer, annotating symbols, slab allocations, and more. (Tweak the second argument to read more or less if needed.) Please share that if you are able to.

[qiyeliu]

KERNEL STACK SIZE: 16384

stack: 0xffff8003a1d74000 ~ ffff8003a1d78000 :

According to sp, the data before and after the stack are as follows, and no obvious stack out-of-bounds information is seen.

>>> task.stack
(void *)0xffff8003a1d74000
>>> hex(trace[0].register("sp"))
'0xffff8003a1d77f50'
>>> print_annotated_memory(0xffff8003a1d77f00, 512)
ADDRESS           VALUE
ffff8003a1d77f00: 0001000000010101
ffff8003a1d77f08: ffff8003a1d77f50 [slab object: thread_stack+0x3f50]
ffff8003a1d77f10: 0001000000010101
ffff8003a1d77f18: 0000000080c00005
ffff8003a1d77f20: 0000000000000087
ffff8003a1d77f28: ffff000048be77e4 [function symbol: schedule_idle+0x24]
ffff8003a1d77f30: ffffffffffffffff
ffff8003a1d77f38: 0000000000000000
ffff8003a1d77f40: 0101010101010101
ffff8003a1d77f48: 0001000000010101
ffff8003a1d77f50: ffff8003a1d77fb0 [slab object: thread_stack+0x3fb0]
ffff8003a1d77f58: ffff0000481284f4 [function symbol: cpu_startup_entry+0x2c]
ffff8003a1d77f60: 0000000000000087
ffff8003a1d77f68: 0000000000000004
ffff8003a1d77f70: 0000000000000004
ffff8003a1d77f78: 0000000000000000
ffff8003a1d77f80: 0000000000000000
ffff8003a1d77f88: 0000000000000000
ffff8003a1d77f90: 0000000000000000
ffff8003a1d77f98: 0000000000000004
ffff8003a1d77fa0: ffff8003a1d77fb0 [slab object: thread_stack+0x3fb0]
ffff8003a1d77fa8: ffff0000481284f4 [function symbol: cpu_startup_entry+0x2c]
ffff8003a1d77fb0: ffff8003a1d77fd0 [slab object: thread_stack+0x3fd0]
ffff8003a1d77fb8: ffff000048096c04 [function symbol: secondary_start_kernel+0x17c]
ffff8003a1d77fc0: 0000000000000004
ffff8003a1d77fc8: ffff0000499c6f88 [object symbol: cpu_topology+0x640]
ffff8003a1d77fd0: 0000000000000000
ffff8003a1d77fd8: 0000000000000000
ffff8003a1d77fe0: 0000000000000000
ffff8003a1d77fe8: 0000000000000000
ffff8003a1d77ff0: 0000000000000000
ffff8003a1d77ff8: 0000000000000000
ffff8003a1d78000: 0000000057ac6e9d