Can strace/ptrace cause a program to crash

strace

So recently, I was discussing strace with somebody, and they were asking what would happen if you straced a running process just as it was creating a network socket or something similar. Could this cause the program to crash in unexpected ways?

From what I've read about ptrace, the syscall used by strace, it shouldn't be able to cause anything like that if you're just debugging a thread. The process gets stopped, every time a syscall is called, but it should later resume and be none the wiser. Signals get queued while it's not running, so I assume something similar happens with syscalls/sockets/listen.

Can ptrace used in the context of strace cause any weird process crashes?

Best Answer

No, strace should not cause a program crash -

Except in this somewhat unusual case:

If it has a bug that depends on timing of execution, or runtime memory locations.

It may trigger this kind of "heisenbug" - but extremely rarely, because this kind of bug is rare, and it needs to only trigger under strace or other instrumentation. And when you find a heisenbug, that's often a good thing.

Regarding ptrace() - the syscall - that is just what strace does inside I think, so it's similar. One can just do more than strace can when using ptrace() directly.

Your example would be just this kind of bug:

In the example, strace would change the timing of the steps to create a network connection. If that causes a problem, it was a "problem waiting to happen" - the timing of execution changes constantly. With strace, just a little more. But any other application could have changed the timing more, like starting a program.

Related Solutions

strace – Strace Hello World Program

This is all perfectly normal. You aren't supposed to prevent the failing library lookups from happening.

execve("./hello", ["./hello"], [/* 62 vars */]) = 0

This is your program starting. Since it is dynamically linked, the first code to execute is from the dynamic loader.

brk(0)                                  = 0x85a5000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb774f000

The dynamic loader is allocating some heap space.

access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)

The dynamic loader checks whether there are dynamic libraries to preload. There aren't any.

open("/home/miguel/GNUstep/Library/Libraries/tls/i686/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries/tls/i686/sse2", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/home/miguel/GNUstep/Library/Libraries/tls/i686/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries/tls/i686", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/home/miguel/GNUstep/Library/Libraries/tls/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries/tls/sse2", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/home/miguel/GNUstep/Library/Libraries/tls/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries/tls", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/home/miguel/GNUstep/Library/Libraries/i686/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries/i686/sse2", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/home/miguel/GNUstep/Library/Libraries/i686/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries/i686", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/home/miguel/GNUstep/Library/Libraries/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries/sse2", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/home/miguel/GNUstep/Library/Libraries/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/home/miguel/GNUstep/Library/Libraries", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/usr/lib/tls/i686/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/tls/i686/sse2", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/usr/lib/tls/i686/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/tls/i686", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/usr/lib/tls/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/tls/sse2", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/usr/lib/tls/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/tls", 0xbf8df160)      = -1 ENOENT (No such file or directory)
open("/usr/lib/i686/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/i686/sse2", 0xbf8df160) = -1 ENOENT (No such file or directory)
open("/usr/lib/i686/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/i686", 0xbf8df160)     = -1 ENOENT (No such file or directory)
open("/usr/lib/sse2/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/sse2", 0xbf8df160)     = -1 ENOENT (No such file or directory)
open("/usr/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3

The dynamic loader is looking for libc6, which is the standard library. It looks in several directories: first in the directories specified in the LD_LIBRARY_PATH, then in the directories listed in /etc/ld.so.conf. (See the manual for the full story.). In each directory, the loader checks several subdirectories first: it determines which hardware features are present (P6 instructions, SSE2), and looks for a version of the library binary which may use these extra features to run more efficiently; when it fails to find one that may use all the features, it looks for a more generic one. In the end, the library is found in a standard system directory, in a non-specialized version.

read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300\177\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=2035943, ...}) = 0
mmap2(NULL, 1801892, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7573000
mmap2(0xb7724000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b0000) = 0xb7724000
mmap2(0xb7729000, 7844, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7729000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7572000
set_thread_area({entry_number:-1, base_addr:0xb7572700, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 (entry_number:6)
mprotect(0xb7724000, 12288, PROT_READ)  = 0
mprotect(0xb7750000, 4096, PROT_READ)   = 0

The standard library is loaded, then its initialization code runs.

fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7571000

This is the result of executing the printf call.

write(1, "Hello World!\n", 13)          = 13
exit_group(0)                           = ?

This is your program exiting, which includes flushing the stdout buffer.

Decode / summarise strace logs

Summary while strace runs

strace has the -c switch which will give you a summary report of the various system calls that were made.

excerpt strace man page

-c      Count time, calls, and errors for each system call and report a 
        summary on program exit.  On Linux, this attempts to show system 
        time (CPU  time  spent  running in the kernel) independent of wall 
        clock time.  If -c is used with -f or -F (below), only aggregate 
        totals for all traced processes are kept.

Example

$ strace -c systemctl list-unit-files --type=service
...
...
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 51.81    0.001831        1831         1           waitid
  8.15    0.000288           7        39           mmap
  7.89    0.000279          19        15           read
  6.11    0.000216           8        26           mprotect
  4.56    0.000161          11        15           open
  2.91    0.000103         103         1           connect
  2.24    0.000079          79         1           clone
  2.15    0.000076          38         2           statfs
  2.01    0.000071           4        19           close
  1.95    0.000069           5        13           poll
  1.90    0.000067           5        14         2 recvmsg
  1.70    0.000060           4        16           fstat
  0.88    0.000031           8         4         3 stat
  0.82    0.000029          29         1           socket
  0.65    0.000023           8         3           munmap
  0.57    0.000020           5         4           sendto
  0.42    0.000015           5         3           ioctl
  0.40    0.000014           7         2           lstat
  0.40    0.000014           7         2           sendmsg
  0.34    0.000012           4         3           brk
  0.23    0.000008           8         1           pipe
  0.23    0.000008           4         2           fcntl
  0.20    0.000007           4         2           rt_sigaction
  0.20    0.000007           7         1         1 access
  0.20    0.000007           4         2           geteuid
  0.17    0.000006           6         1           execve
  0.14    0.000005           5         1           getsockname
  0.11    0.000004           4         1           dup2
  0.11    0.000004           4         1           getresuid
  0.11    0.000004           4         1           getresgid
  0.11    0.000004           4         1           arch_prctl
  0.08    0.000003           3         1           rt_sigprocmask
  0.08    0.000003           3         1           getrlimit
  0.08    0.000003           3         1           set_tid_address
  0.08    0.000003           3         1           set_robust_list
  0.00    0.000000           0         4           write
  0.00    0.000000           0         1           kill
------ ----------- ----------- --------- --------- ----------------
100.00    0.003534                   207         6 total

Analyzing strace logs postmortem

I found this Perl scripts called Strace_analyzer.pl which sounds like what you're looking for.

Usage

$ ./strace_analyzer_ng_0.03.pl -help
Usage: strace-analyze [OPTION]… [FILE]
Analyzes strace output for IO functions. It creates statistics
on IO functions and performance of the read and write functions.
The strace file should have been run with ‘strace -tt [PROGRAM]

There's an example of the output on the page I linked to above. It's too long to post here. I've posted here on pastebin.com as well.

Alternative to strace, ioapps

I came across this app called ioapps which can give you a more visual breakdown of what your app is doing when it's running. Perhaps this might be better for what you're trying to accomplish than processing strace logs.

Usage

  $ ioprofiler-trace thunderbird
Once it loads, we just close the thunderbird window and check we have a trace log called "ioproftrace.log" because that's the default name of the log (one can specify another name using -o command line option):
  $ ls -l ioproftrace.log 
  -rw-r--r-- 1 user user 74890554 Apr  4 22:04 ioproftrace.log
It seems OK, so we can run ioprofiler over it:
  $ ioprofiler ioproftrace.log 

Example GUI

Another alternative to strace, strace+

NOTE: The project, strace+, is no longer being maintained, and in fact many of its features have been merged into the default strace via the -k switch. So you might want to make sure your version of strace is at least up to 4.9, which is when that switch was merged in.