Finding out where syscalls are called from: Stack traces with strace

[aheck]

https://abstractexpr.com/2024/06/08/finding-out-where-syscalls-are-called-from-stack-traces-with-strace/

[tanelpoder]

There's also strace -kk (--stack-trace=source), but when I just ran it on Ubuntu 24.04, got this error:

  $ strace -kk pwd
  strace: Stack traces with source line information (-kk/--stack-trace=source option) are not supported by this build of strace

Also, there's "perf trace" that has now gotten pretty good reporting the system call arguments and context (in older versions it didn't report enough details of the system call arguments & their contents).

As strace uses userspace ptrace(), it slows down the traced processes and may even cause failures due to mucking around with signalling, perf trace doesn't have that problem as it uses kernel tracepoints.

[fjfaase]

strace is a rather powerfull tool if you want to find out what a certain executable is doing. Which files it is opening, reading and writing and also which other executables it is executing. I personally have not used the '--stack-trace' option yet.

Earlier this year, I have used it to analyze what happens during the initial steps of live-bootstrap [1] and produce a web page with all the information [2]. For this, I wrote a C program to parse and process the output of strace.

[1] https://github.com/fosslinux/live-bootstrap

[2] https://fransfaase.github.io/Emulator/

[ranger_danger → fjfaase]

And if you want to do the same thing on a whole-system level, bpftrace is invaluable. With tools like opensnoop/execsnoop/etc. you can see all the files and processes being run and by what. There are network-level similar bpf tools also.

[amelius → fjfaase]

What flags do you use when you just want to see the files that are being opened? I'm always grepping, but there must be an easier way.

[Amezarak → amelius]

strace -e trace=open -f -p pid

If you want to see all file-related calls, replace "open" with "file" or you could add the calls one by one: e.g., trace=open,read.

[hawski]

I feel stupid, because I didn't know strace can do this, I did it once with a gdb script:

https://gist.github.com/hadrianw/5b8d33a4b353c49e7dbd6eb55f8...

My learning: RTFM.

[tanelpoder → hawski]

Older versions of strace (like in RHEL 7) did not have such an option.

[mshockwave]

Today I definitely learned! I feel like we can just patch strace to read debug info (and use it in stack trace) when present.

[spcharc]

It can be useful I think.

Trying this on my toy project. This is a single thread program so it cannot do syscall from multiple cores.

It is not very helpful without debug info:

  nanosleep({tv_sec=1, tv_nsec=299127292}, NULL) = 0
   > /home/spcharc/proj/out() [0x80f1]
  write(1, "g1() ===== end =====\n", 21g1() ===== end =====
  )  = 21
   > /home/spcharc/proj/out() [0x80f1]
  munmap(0x7a267b491000, 66580)           = 0
   > /home/spcharc/proj/out() [0x80ec]
  exit(0)                                 = ?
  +++ exited with 0 +++
   > /home/spcharc/proj/out(+0x0) [0x80e7]

With debug info added, the output looks much better:

  nanosleep({tv_sec=1, tv_nsec=297422159}, NULL) = 0
   > /home/spcharc/proj/out(assert(bool, char const*)+0x14a) [0x87a8]
   > /home/spcharc/proj/out(fd_manager::wait_event(timespec const*, timespec&, epoll_event*, unsigned int)+0xbe) [0x5598]
   > /home/spcharc/proj/out(event_loop::execute_tasks()+0x56) [0x6a10]
   > /home/spcharc/proj/out(event_loop::main_loop()+0x5b) [0x6b19]
   > /home/spcharc/proj/out(main+0x184) [0x77c6]
   > /home/spcharc/proj/out(assert(bool, char const*)+0xc0) [0x871e]
  write(1, "g1() ===== end =====\n", 21g1() ===== end =====
  )  = 21
   > /home/spcharc/proj/out(assert(bool, char const*)+0x14f) [0x87ad]
   > /home/spcharc/proj/out(static_file_buffered_printer<1u, 1012u>::flush()+0x75) [0x5071]
   > /home/spcharc/proj/out(output_stream<static_file_buffered_printer<1u, 1012u> >::operator<<(Manip)+0x74) [0x3624]
   > /home/spcharc/proj/out(g1(event_loop*, uptr_t)+0x14c) [0x74bc]
   > /home/spcharc/proj/out(assert(bool, char const*)+0x12d) [0x878b]
  munmap(0x7b80db5fd000, 66580)           = 0
   > /home/spcharc/proj/out(assert(bool, char const*)+0x14a) [0x87a8]
   > /home/spcharc/proj/out(main+0x1bd) [0x77ff]
   > /home/spcharc/proj/out(assert(bool, char const*)+0xc0) [0x871e]
  exit(0)                                 = ?
  +++ exited with 0 +++
   > /home/spcharc/proj/out(assert(bool, char const*)+0x145) [0x87a3]
   > /home/spcharc/proj/out(assert(bool, char const*)+0xc8) [0x8726]

Interesting that every syscall is from assert(). My assert() is basically "if (!cond) {print(msg); exit(1);}".

I guess it traced to some unrecognized area and stopped there.

[rcxdude → spcharc]

Does your main have an assert(false) after the main loop? If so the return address could be set to the assert function as some kind of optimization.

[spcharc → rcxdude]

I do have a couple of asserts in my code, but that does not explain why every stack trace begins and ends with "assert()"

Actually I call syscalls from assembly, and my _start() is also an assembly function. That is why this happens I guess. strace somehow doesn't play well with code written in .s file?

[rcxdude → spcharc]

The backtrace code probably won't, as it'll be depending on the C calling convention to generate it. It's also possible assert() is just the function at the start or end of your text section, so any address that falls outside the range in that direction gets attributed to it, including values the stack walker incorrectly thinks are addresses.

[gdgghhhhh]

Perf trace is also worth noting. It was much less performance overhead than strace. https://man7.org/linux/man-pages/man1/perf-trace.1.html

[aheck]

One of the great strengths of strace as a debugging tool is that it shows you what a program is doing regardless of whether it was compiled with debug info or not. The downside of this is that you only see the program’s syscall. You can use this information to deduce what is happening in the program but you don’t see from where in the program those syscalls originate...

[thundergolfer → aheck]

Why did you just quote the start of the article?

[codetrotter → thundergolfer]

He's the person that submitted the post. I assume he added it for context.