Kevin's Worklog

Documenting the Daily Stream

Strace and Apache

Adding a new tool to my toolbox: strace. I’m surprised I haven’t used it before as it seems very useful.

So what is it? Strace is a debugging utility for Linux and some other Unix-like systems to monitor the system calls used by a program and all the signals it receives. So, for instance, to monitor Apache on Ubuntu, I can (while the Apache process is running) start strace like:

ps auxw | grep sbin/apache | awk '{print"-p " $2}' | sudo xargs strace

Then perform an action (e.g. request a webpage) and I’ll have some useful output to look over:

[pid  9669] <... accept4 resumed> {sa_family=AF_INET6, sin6_port=htons(36244), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 18
[pid  9669] getsockname(18, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
[pid  9669] fcntl(18, F_GETFL)          = 0x2 (flags O_RDWR)
[pid  9669] fcntl(18, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid  9669] read(18, "GET /archive/square_thumbnails/d"..., 8000) = 523
[pid  9669] stat("/var/www/omeka/archive/square_thumbnails/d1e08e21f0cb91e12f5be093225ec7ac.jpg", 0x7fff2f2cc110) = -1 EACCES (Permission denied)
[pid  9669] lstat("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  9669] lstat("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  9669] open("/var/www/.htaccess", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid  9669] lstat("/var/www/omeka", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  9669] open("/var/www/omeka/.htaccess", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid  9669] lstat("/var/www/omeka/archive", {st_mode=S_IFLNK|0777, st_size=38, ...}) = 0
[pid  9669] stat("/var/www/omeka/archive", 0x7fff2f2cc090) = -1 EACCES (Permission denied)
[pid  9669] write(7, "[Mon Aug 04 15:33:25.627750 2014"..., 172) = 172
[pid  9669] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f146758e000
[pid  9669] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f146758c000
[pid  9669] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f146758a000
[pid  9669] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1467588000
[pid  9669] read(18, 0x7f1467590048, 8000) = -1 EAGAIN (Resource temporarily unavailable)
[pid  9669] writev(18, [{"HTTP/1.1 403 Forbidden\r\nDate: Mo"..., 216}, {"<!DOCTYPE HTML PUBLIC \"-//IETF//"..., 334}], 2) = 550
[pid  9669] write(10, "127.0.0.1 - - [04/Aug/2014:15:33"..., 272) = 272
[pid  9669] times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1736382825

This gives me a lot of detail into what Apache is doing on the system. I can see what files it’s requesting and where it’s having problems.