Scenario
--------------------
Suppose some program on your system refuses to work or it works, but much slower than you’ve expected. How can you investigate the reason of such undesirable behavior? This technique will often be helpful in troubleshooting, PHP issues as well. Let us see how to use the strace command.
What is strace
-------------------
Strace is quite simply a tool that traces the execution of system calls. In its simplest form it can trace the execution of a binary from start to end, and output a line of text with the name of the system call, the arguments and the return value for every system call over the lifetime of the process.
Use of strace command
--------------------------------
Commonly to use strace you should give the following command:
strace -o outputfile command
Here , I am attempting to grasp the system calls during the file creation from a users shell, where he fails to create or update a file using the command “touch /tmp/file”
strace -o strace.out touch /tmp/file
Here
-o strace.out option means that strace program will output all information to the file named strace.out;
touch /tmp/file is the program with arguments which is to be straced.
Strace command results
So this is what we have in strace.out:
$ cat strace.out
execve(“/usr/bin/touch”, [“touch”, “/tmp/file”], [/* 58 vars */]) = 0
brk(0) = 0x871c000
access(“/etc/ld.so.nohwcap”, F_OK) = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb77a0000
access(“/etc/ld.so.preload”, R_OK) = -1 ENOENT (No such file or directory)
open(“/etc/ld.so.cache”, O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=81742, …}) = 0
mmap2(NULL, 81742, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb778c000
close(3) = 0
access(“/etc/ld.so.nohwcap”, F_OK) = -1 ENOENT (No such file or directory)
open(“/lib/i386-linux-gnu/libc.so.6”, O_RDONLY|O_CLOEXEC) = 3
read(3, “\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340\233\1\0004\0\0\0″…, 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1754876, …}) = 0
mmap2(NULL, 1763964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75dd000
mmap2(0xb7786000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a8000) = 0xb7786000
mmap2(0xb7789000, 10876, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7789000
close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75dc000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb75dc940, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb7786000, 8192, PROT_READ) = 0
mprotect(0x8055000, 4096, PROT_READ) = 0
mprotect(0xb77c3000, 4096, PROT_READ) = 0
munmap(0xb778c000, 81742) = 0
brk(0) = 0x871c000
brk(0x873d000) = 0x873d000
open(“/usr/lib/locale/locale-archive”, O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=8752496, …}) = 0
mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb73dc000
mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x855000) = 0xb779f000
close(3) = 0
open(“/tmp/file”, O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK|O_LARGEFILE, 0666) = -1 EACCES (Permission denied)
utimensat(AT_FDCWD, “/tmp/file”, NULL, 0) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++
In this case we can see that the system calls to create the file or update the time stamp faces permission issues
open(“/tmp/file”, O_WRONLY|O_NONBLOCK|O_CREAT|O_NOCTTY|O_LARGEFILE, 0666) = -1 EACCES (Permission denied)
Lets us cross check the permission of /tmp/file
$ls -l /tmp/file
---------- 1 geo geo 0 Aug 6 13:22 /tmp/file
So it is evident that the file permissions were the culprit here. So I went ahead and changed the permissions
$ chmod 644 /tmp/file
Now check the relevant parts of the strace results again
mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x855000) = 0xb7718000
close(3) = 0
open(“/tmp/file”, O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK|O_LARGEFILE, 0666) = 3
dup2(3, 0) = 0
close(3) = 0
utimensat(0, NULL, NULL, 0) = 0
close(0) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++
