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

Skip to content
 

Abstract Expression

Software Development Blog

Menu
Search

  * Home
  * About
  * Contact

Search for: [                    ] Search
[strace-stack]

Finding out where Syscalls are Called From: Stack Traces with Strace

On 8. June 20248. June 2024 By Andreas Heck

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.

The good news is that if your program was compiled with debug info
strace can actually show a stack trace for every syscall in your
binary.

Example

To demonstrate this we just save the following program to hello.c:

#include <stdio.h>

void print_info()
{
    int num = 5;
    printf("== Info ==\n");
    printf("Hello World!\n");
    printf("Num: %d\n", num);
}

int main(int argc, char **argv)
{
    print_info();
    return 0;
}

This program uses the printf function to print three lines of output.
This function is part of the C standard library. To actually output
the text it has to call the operating system by using the syscall
write. We will look for this later in the strace output.

To compile the program we enter the following command:

$ gcc -g -o hello hello.c

Now we can run it with strace using the --stack-trace option
(alternatively you can use the equivalent short-form option-k):

$ strace --stack-trace ./hello

This will give us an output similar to this:

...
write(1, "Num: 5\n", 7Num: 5
)                 = 7
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__write+0x14) [0x11c574]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_file_write+0x35) [0x93965]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_do_write+0xb1) [0x92561]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_file_xsputn+0xcf) [0x93a9f]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(parse_printf_format+0xaf9) [0x60cb9]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_vfprintf+0x48e3) [0x6b733]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_printf+0xb3) [0x601a3]
 > /home/user/abstractexpr/strace-stacktrace/hello(print_info+0x4a) [0x11b3]
 > /home/user/abstractexpr/strace-stacktrace/hello(main+0x1d) [0x11d3]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_init_first+0x8a) [0x2a1ca]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x8b) [0x2a28b]
 > /home/user/abstractexpr/strace-stacktrace/hello(_start+0x25) [0x10a5]
exit_group(0)                           = ?
+++ exited with 0 +++
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_exit+0x1d) [0xee21d]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(erand48_r+0x196) [0x47a26]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(exit+0x1e) [0x47bae]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_init_first+0x91) [0x2a1d1]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x8b) [0x2a28b]
 > /home/user/abstractexpr/strace-stacktrace/hello(_start+0x25) [0x10a5]

What we see here is that after every syscall (in this example only
write and exit_group are shown) strace prints a stack trace that led
to the call of the syscall. The stack trace has to be read from the
bottom to the top with the top line being the function that made the
actual syscall.

Most of the lines in the stack trace are function calls in the
dynamically linked standard library (libc.so.6). But if you look
closely you will see two lines that refer to functions in our hello
program:

...
 > /home/user/abstractexpr/strace-stacktrace/hello(print_info+0x4a) [0x11b3]
 > /home/user/abstractexpr/strace-stacktrace/hello(main+0x1d) [0x11d3]
...

We can see here that main has called print_info before the flow of
control went to printf and from there deeper into the standard
library.

At the end of each line, we see an address in square brackets. This
is the address from where the function call occurred that ultimately
led to the syscall. Unfortunately, strace doesn't show us the source
code file and the line number that this address relates to. But we
can easily get this information with the addr2line tool:

$ addr2line -e hello 0x11b3
/home/user/abstractexpr/strace-stacktrace/hello.c:9

Prettifying the Stack Trace

Now that we know how to resolve a single address we could write a
Python script to replace every single address in the output of strace
with the output of addr2line.

I've already written such a script:

#!/usr/bin/env python3

import os
import sys

import subprocess

def usage():
    print("Usage: pretty_print_strace.py FILENAME")
    sys.exit(2)

if len(sys.argv) != 2:
    usage()

filename = sys.argv[1]

def handle_line(line):
    line = line.rstrip()
    if not line.startswith(" > ") or not line.endswith("]"):
        print(line)
        return
    enrich_line(line)

def enrich_line(line):
    line = line[3:]
    components = line.split(" ")
    binary_funcoffset = components[0]
    address = components[1]
    binary = binary_funcoffset.split("(")[0]
    address = address[1:]
    address = address[:-1]

    result = subprocess.run(["addr2line", "-e", binary, address], shell=False, capture_output=True, text=True)
    line_num_info = ""
    if result.returncode != 0:
        line_num_info = address
    else:
        line_num_info = result.stdout.rstrip()

    if line_num_info == "??:?":
        line_num_info = address

    print(f" > {binary_funcoffset} [{line_num_info}]")

with open(filename) as f:
    for line in f:
        handle_line(line)

Save it as pretty_print_strace.py and make it executable with:

$ chmod a+x pretty_print_strace.py

You can then execute strace again but use the -o option to tell it to
write its output to a file:

$ strace -o strace.out -stack-trace ./hello

This output file can then be prettified with the following command:

$ ./pretty_print_strace.py strace.out > strace-pretty.out

The stack traces in the newly created file strace-pretty.out will
then have a filename and a line number instead of an address for
every stack trace entry where addr2line could resolve the address:

...
write(1, "Num: 5\n", 7)                 = 7
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__write+0x14) [./io/../sysdeps/unix/sysv/linux/write.c:26 (discriminator 1)]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_file_write+0x35) [./libio/./libio/fileops.c:1182]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_do_write+0xb1) [./libio/./libio/fileops.c:449 (discriminator 1)]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_file_xsputn+0xcf) [./libio/./libio/fileops.c:1244 (discriminator 2)]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(parse_printf_format+0xaf9) [./stdio-common/./stdio-common/printf_buffer_to_file.c:59 (discriminator 2)]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_vfprintf+0x48e3) [./stdio-common/./stdio-common/vfprintf-internal.c:1545]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_IO_printf+0xb3) [./stdio-common/./stdio-common/printf.c:37]
 > /home/user/abstractexpr/strace-stacktrace/hello(print_info+0x4a) [/home/user/abstractexpr/strace-stacktrace/hello.c:9]
 > /home/user/abstractexpr/strace-stacktrace/hello(main+0x1d) [/home/user/abstractexpr/strace-stacktrace/hello.c:14]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_init_first+0x8a) [./csu/../sysdeps/x86/libc-start.c:74]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x8b) [./csu/../csu/libc-start.c:128]
 > /home/user/abstractexpr/strace-stacktrace/hello(_start+0x25) [0x10a5]
exit_group(0)                           = ?
+++ exited with 0 +++
 > /usr/lib/x86_64-linux-gnu/libc.so.6(_exit+0x1d) [./posix/../sysdeps/unix/sysv/linux/_exit.c:30 (discriminator 1)]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(erand48_r+0x196) [./stdlib/./stdlib/exit.c:131]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(exit+0x1e) [:?]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_init_first+0x91) [./csu/../sysdeps/x86/libc-start.c:63]
 > /usr/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x8b) [./csu/../csu/libc-start.c:128]
 > /home/user/abstractexpr/strace-stacktrace/hello(_start+0x25) [0x10a5]

Interestingly, many locations in the standard library could be
resolved here as well.

The two lines from our program look like this now:

...
 > /home/user/abstractexpr/strace-stacktrace/hello(print_info+0x4a) [/home/user/abstractexpr/strace-stacktrace/hello.c:9]
 > /home/user/abstractexpr/strace-stacktrace/hello(main+0x1d) [/home/user/abstractexpr/strace-stacktrace/hello.c:14]
...

So here we have it! A stack trace for every syscall recorded by
strace and the name of the C file and the line number are present in
every entry of the stack trace.

Teilen mit:

  * Twitter
  * Facebook
  * 

Like Loading...

Related

Cdebugginglinuxstrace

Post navigation

Previous

Introduction to Strace

Leave a comment Cancel reply

 [                                             ] 
 [                                             ] 
 [                                             ] 
 [                                             ] 
 [                                             ] 
 [                                             ] 
 [                                             ] 
D[                                             ] 

Search

Search for: [                    ] Search
Follow me on Social Media

Twitter: https://twitter.com/AndreasHeck1

GitHub: https://github.com/aheck

  * Legal Disclosure
  * Privacy Policy

Blog at WordPress.com.

  * Comment
  * Reblog
  * Subscribe Subscribed
      + [wpcom-] Abstract Expression
        [                    ]
        Sign me up
      + Already have a WordPress.com account? Log in now.
  * 
      + [wpcom-] Abstract Expression
      + Customize
      + Subscribe Subscribed
      + Sign up
      + Log in
      + Copy shortlink
      + Report this content
      + View post in Reader
      + Manage subscriptions
      + Collapse this bar

[Close and accept] Privacy & Cookies: This site uses cookies. By
continuing to use this website, you agree to their use.
To find out more, including how to control cookies, see here: Cookie
Policy
%d

[b]