How Should Strace Be Used

How should strace be used?

Strace Overview

strace can be seen as a light weight debugger. It allows a programmer / user to quickly find out how a program is interacting with the OS. It does this by monitoring system calls and signals.

Uses

Good for when you don't have source code or don't want to be bothered to really go through it.

Also, useful for your own code if you don't feel like opening up GDB, but are just interested in understanding external interaction.

A good little introduction

Here is a gentle introduction to using strace to debug process hangs: strace introduction

how do i use strace to know about system calls in my C program

By running your program through strace:

strace path/to/your/executable

e.g. strace ./myapp

Strace With C Executable?

Your malloc does not issue any syscalls (e.g. brk) for small values of x (e.g. 23)

That is because the prior scanf call has to [internally] call malloc. The internal malloc calls brk.

The heap already has enough space allocated, so your malloc can fulfill the request without calling brk.

To be able to see this, put a usleep(1) before your malloc call and after. This generates innocuous calls to the nanosleep syscall which serve as markers around your malloc call.

---

Here is the strace output for an input value of 23:

execve("./fix1", ["./fix1"], 0x7ffea3366ac0 /* 94 vars */) = 0
brk(NULL)                               = 0x15fc000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffcf4a51d40) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=340324, ...}) = 0
mmap(NULL, 340324, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f15ef9bf000
close(3)                                = 0
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 E\2\0\0\0\0\0"..., 832) = 832
lseek(3, 792, SEEK_SET)                 = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0g\225=\371\27\203\227A\277:}7a\216\376\301"..., 68) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=2786704, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15ef9bd000
lseek(3, 792, SEEK_SET)                 = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0g\225=\371\27\203\227A\277:}7a\216\376\301"..., 68) = 68
lseek(3, 864, SEEK_SET)                 = 864
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 1857472, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f15ef7f7000
mprotect(0x7f15ef819000, 1679360, PROT_NONE) = 0
mmap(0x7f15ef819000, 1363968, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7f15ef819000
mmap(0x7f15ef966000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16f000) = 0x7f15ef966000
mmap(0x7f15ef9b3000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bb000) = 0x7f15ef9b3000
mmap(0x7f15ef9b9000, 14272, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f15ef9b9000
close(3)                                = 0
arch_prctl(ARCH_SET_FS, 0x7f15ef9be500) = 0
mprotect(0x7f15ef9b3000, 16384, PROT_READ) = 0
mprotect(0x403000, 4096, PROT_READ)     = 0
mprotect(0x7f15efa3c000, 4096, PROT_READ) = 0
munmap(0x7f15ef9bf000, 340324)          = 0
fstat(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x1), ...}) = 0
brk(NULL)                               = 0x15fc000
brk(0x161d000)                          = 0x161d000
brk(NULL)                               = 0x161d000
read(0, "23\n", 1024)                   = 3
nanosleep({tv_sec=0, tv_nsec=1000}, NULL) = 0
nanosleep({tv_sec=0, tv_nsec=1000}, NULL) = 0
lseek(0, -1, SEEK_CUR)                  = -1 ESPIPE (Illegal seek)
exit_group(0)                           = ?
+++ exited with 0 +++

---

However, a large value will cause your malloc to issue an mmap syscall.

Here is the the output for a value of 1000000000:

execve("./fix1", ["./fix1"], 0x7ffe4ec746d0 /* 94 vars */) = 0
brk(NULL)                               = 0x13df000
arch_prctl(0x3001 /* ARCH_??? */, 0x7ffe5a768930) = -1 EINVAL (Invalid argument)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=340324, ...}) = 0
mmap(NULL, 340324, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f61b6e83000
close(3)                                = 0
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 E\2\0\0\0\0\0"..., 832) = 832
lseek(3, 792, SEEK_SET)                 = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0g\225=\371\27\203\227A\277:}7a\216\376\301"..., 68) = 68
fstat(3, {st_mode=S_IFREG|0755, st_size=2786704, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f61b6e81000
lseek(3, 792, SEEK_SET)                 = 792
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0g\225=\371\27\203\227A\277:}7a\216\376\301"..., 68) = 68
lseek(3, 864, SEEK_SET)                 = 864
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 1857472, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f61b6cbb000
mprotect(0x7f61b6cdd000, 1679360, PROT_NONE) = 0
mmap(0x7f61b6cdd000, 1363968, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7f61b6cdd000
mmap(0x7f61b6e2a000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16f000) = 0x7f61b6e2a000
mmap(0x7f61b6e77000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bb000) = 0x7f61b6e77000
mmap(0x7f61b6e7d000, 14272, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f61b6e7d000
close(3)                                = 0
arch_prctl(ARCH_SET_FS, 0x7f61b6e82500) = 0
mprotect(0x7f61b6e77000, 16384, PROT_READ) = 0
mprotect(0x403000, 4096, PROT_READ)     = 0
mprotect(0x7f61b6f00000, 4096, PROT_READ) = 0
munmap(0x7f61b6e83000, 340324)          = 0
fstat(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x1), ...}) = 0
brk(NULL)                               = 0x13df000
brk(0x1400000)                          = 0x1400000
brk(NULL)                               = 0x1400000
read(0, "1000000000\n", 1024)           = 11
nanosleep({tv_sec=0, tv_nsec=1000}, NULL) = 0
mmap(NULL, 1000001536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f617b30e000
nanosleep({tv_sec=0, tv_nsec=1000}, NULL) = 0
lseek(0, -1, SEEK_CUR)                  = -1 ESPIPE (Illegal seek)
exit_group(0)                           = ?
+++ exited with 0 +++

---

Here is the program I used to generate the above. Note that anything that generates a syscall that is not part of scanf or malloc could replace the usleep calls (e.g. time):

#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

void
main()
{
    int x;

    scanf("%d", &x);
    usleep(1);
    malloc(x);
    usleep(1);
}

---

UPDATE:

Can you please explain why this won't work: [redacted for space] – ariel

Using write should be fine. It's "innocuous" and the write syscalls should show up just fine. As I mentioned, any syscall could be used [if it's uniquely distinguishable from anything that scanf or malloc would do].

and why you said "not part of scanf"? – ariel

Because [as I mentioned] scanf will do a malloc [and a free--but that probably won't generate a syscall].

Even with large numbers I don't see malloc being called. – ariel

I'm not sure what's going on in your setup. I used 1,000,000,000 to really force the issuance of a syscall by your malloc.

Either the nanosleep or your write syscalls should work as markers.

Do you see an mmap call in your trace [or more brk calls] between the marker calls?

---

UPDATE #2:

Plus, I can't get an input to make it show sbrk() how can I do that – ariel

It's up to the individual heap manager to decide which of the syscalls sbrk, brk, and/or mmap it will use and when.

On my system [linux], I'm using the malloc from glibc. My suspicion is that it only does brk and not sbrk

brk and sbrk are similar enough that a given manager will likely use one or the other but not both -- YMMV.

From man sbrk:

On Linux, sbrk() is implemented as a library function that uses the
brk() system call, and does some internal bookkeeping so that it can
return the old break value.

How to track child process using strace?

strace -f to trace child process that's fork()ed.

Strace daemon process started using service

Instead of running the nginx from service. Run service nginx stop and then run

strace nginx -g "daemon off;"

this will make sure that you get the trace of the process. The -g "daemon off;" will make sure the nginx is not run as a daemon process, else again the strace would end

Service command is just activating a process and if you want to strace it the best is to launch the process directly.

In case you are still interested in debugging the process started using the service command. Then do below

service nginx start
ps aux | grep nginx

Capture the pid from the nginx process and then attach to it using

strace -p <pid>

Forking Processes

To trace processes which fork, you need to use the -f flag

strace -f nginx

Service tracing

When you call service start nginx, assuming the system uses systemd, the call gets translated to systemctl start nginx. Now if you look at the source code of systemd

https://github.com/systemd/systemd/blob/cf45dd36282368d5cdf757cac2cf1fc2b562dab2/src/systemctl/systemctl.c#L3100

r = sd_bus_call_method_async(
    bus,
    NULL,
    "org.freedesktop.systemd1",
    "/org/freedesktop/systemd1",
    "org.freedesktop.systemd1.Manager",
    "Subscribe",
    NULL, NULL,
    NULL);

It doesn't spawn/fork the process. It sends the message to the systemd service which then starts nginx process.

So in short, NO you can't strace through your service nginx start command.

how should I use strace to snif the serial port?

Try it out with someting simple.

strace -e write=1 echo foo

This will write all syscalls, and in addition to these, the data written to fd 1.

strace -e trace=none -e write=1 echo foo

This will generate no output except for the output from the program itself. It seems you have to trace write if you want to see its data.

strace -e trace=write -e write=1 echo foo

This will print all write syscalls, for any file descriptor. In addition to that, it will print a dump of the data sent to descriptor 1. The output will look like this:

write(1, "foo\n", 4foo
)                    = 4
 | 00000  66 6f 6f 0a                                       foo.             |
+++ exited with 0 +++

The syscall starts in the first line. After the list of arguments, the syscall is actually executed, and prints foo followed by a newline. Then the syscall return value is printed by strace. After that, we have the data dump.

I'd suggest using -e trace=write -e write=4 -o write4.txt followed by grep '^ |' write4.txt or something like that. If you want to see data in real time, you can use a bash redirection like this:

strace -e trace=write -e write=4 -o >(grep '^ |') ./myapp

This will send output from strace to grep, where you can strip the write syscalls and concentrate on the data dumps.

The extremely weird part is that the line serial fd = 4 is also a printf statement, but for some reason it is not wrapped around write(fd, ....) statement in strace output. Can someone explain that, too?

I'd say that line is output not from strace, but from some application. That's the reason it is not wrapped. The fact that no wrapped version of this appears in addition to that unwrapped one (like in my foo example output above) suggests that the output might originate in a child process lainced by myapp. Perhaps you want to add -f so you follow child process creation?

Notice that a child might decide to rename its file descriptors, e.g. redirect its standard output to that serial port opened by the parent. If that happens, write=4 won't be appropriate any more. To be on the safe side, I'd write the whole -f -e trace=write output to a file, and look at that to see where the data actually gets written. Then adjust things to home in on that data.

How to regex strace process?

Like this:

sudo strace -f -p1523 -e write 2>&1 | grep -o 'write([^)]\+)'

or with bash:

sudo strace -f -p1523 -e write |& grep -o 'write([^)]\+)'

Output

write(6, "\26\3\1\2\0\1\0\1\374\3\3\247\321\336S\265c\321]\322\276\273\361]\24\313e\341c2a\334"..., 517)
write(6, "\26\3\3\0F\20\0\0BA\4\223\26\337\256\244\3429\306p\216\3231Zt\346xhi\343\261\215"..., 126)
write(6, "\27\3\3\1\230D\374\356\350\233O\305K\246\331`\311\300\265y\215\225\201\33\364\335\336\336\231\311z\355"..., 413)
write(6, "\25\3\3\0\32D\374\356\350\233O\305L\357\313\226\302$U?a\304\250s\264\16)
write(1, "None\n", 5)

---

Related Topics