Spying on Apache and PHP with Strace

this video is called spying on Apache and PHP with estrus so let's say that you're a Linux system in and your users are complaining that one of their blogs let's call it my random blog comm is slow so the first thing that we're going to want to do is we're going to want to verify that the site is really slow and that the users aren't crazy because sometimes they are so we're going to log in to the web server we're just going to quickly verify that the problem exists so I'm going to use my old pal telnet and I'm going to tell it to localhost port 80 so I'm on the web server so this is going to connect to one of my Apache processes and I'm going to start talking HTTP at it like like I was a web browser so I'm going to say get slash HTTP 1.1 that's the flavor I'm talking and I want to say I am virtual host my random blog.com and here I can just keep entering HTTP headers all day long if I wanted to I could say something like user agent my brain but I'm not going to so if I hit return twice that's assigned to Apache that I want my results and I'm done entering headers so here we go two new lines in a row and you can see Apaches just spinning here I was waiting a good five seconds before I got any results here so in here you can see some HTML got spewed out to stand it out so you can kind of see this is a wordpress site we're talking to my good friend my random blog okay so step one completed the users are not crazy and the site is actually slow so the next thing I want to show you is how to figure out which Apache work a process that you're talking to when you use telnet to connect locally to the web server so let's connect again so now this time I'm not going to hit return twice I'm going to leave it connected to the web server and since I'm running screen I'm going to pop open a new screen I'm going to sudo up I'm going to run LSO F with the Pitt option try to figure out which TCP port my telnet is connected to locally so you can see this TCP connection for telnet is five port five six nine eight six so now I'm going to use net step five six nine eight six to figure out which Apache process I'm talking to so we all know a TCP connection has a source port and a destination port so I used LSO F to get all the files opened by my telnet process and since a TCP socket is just file since the UNIX everything is a file it shows me TCP sockets as well so the source port here five six nine eight six which I then used for my grep and netstat I use netstat which with the dash n to not do dns lookups - a to show me everything and P to show me the process names so you can kind of see here that pid' one six seven three eight is my apache process now I'm going to pop up another window I'm going to run top I'm going to say I just want to see Apache so one six seven three eight I was attached to this guy so let's see if I'm still attached it doesn't look like it so you can see what happened is Apache ended up getting tired of waiting around for me and decided to stay throw a 400 here now you can see why Apache might not wait forever for me to finish entering my HTTP headers because I guess I couldn't I connect to every Apache worker on this machine and just hang them so you know that's kind of a denial of service attack so it's good that Apache only waits so long for you one thing I want to do before we go too much further it's organized my screen so I've got a few of them going and I just want to make sure I don't get lost so this is by telnet screen this is my root spy screen and this is my top screen all right now I can see where I'm going now that I've shown you how to identify which Apache Worker process your telnet session is connected to I'm going to show you how to spy on it using s trace what is s trace s trace is a program that you can attach to a running program that prints out every system call the program makes along with its arguments you can also run it in a standalone mode as well why is this useful well you can learn an awful lot about what a program is doing just by watching it system calls I mean let's take four basic system calls open closed read and write with just these four you can see how a program communicates over the network since TCP UDP and UNIX domain sockets are all just files basically you can also see what it's reading from files and what it's writing to files that's very very useful now when we're going to attach s trace to Apache the arguments that we're going to be interested in are - Oh file this is where s trace outputs its information - so we'll be including that one - peep it we're going to be using this one to connect to the running Apache process - Esther sighs this tells as tres that we want to see in my case 4k worth of data from every system call arguments so in a read or write for example I'd like to see a lot of information about what's being read or what's being written more than about 4k I'm not really interested in so and we are also going to use another argument called - R and - are prints a relative timestamp of each system call so this way we'll be able to figure out what is slow right so that's how we're going to use s trace so let's get started the first thing we're going to want to do is we're going to want to tell MIT back to localhost going to go back to our loops going to go back to our screen session or spy section here okay all right so we're going to attach s trace one six seven four - when I go back here to our telnet session hit return a couple times and we're waiting okay now that that's done we can go back here and hit ctrl C on our s trace and we should have a bunch of really good information in temp output let's take a look at what we got so here we go this is the pit that we connected to one six seven four to this guy and you can see this right here this is the relative is the - our switch working for us this tells us that between this system call and this system call two point six six seconds of wall clock time had elapsed and this is kind of cool you can see this is me or excuse me this is the Apache worker reading from its port AV socket backslash R backslash n from me and that's when I went over and hit return and it was a is probably waiting about two point six six seconds for me to smack the return key so indi you can see you know there's a whole bunch of system calls in here change directory to var dub dub dub HTML it's statting index.php so this is pretty interesting but the system calls you can really get an idea of what the apache worker is doing so everything here is happening really fast like it's allocating some memory it's closing some file descriptors it's opening some files like this open call you can see that addicts succeed it succeeded because it got a file descriptor back file descriptor 11 and then they can later it can do some various other operations on file descriptor 11 and then later on it closes it so you can track file descriptors that way now what we want to do is we want to somehow sort these so we can see all the we want to see what the slow stuff is so let's sort this so I'm going to say cat temp output and I'm going to cut and this is about 12 characters through 16 characters maybe you know just a few of these and I'm going to sort - are n and I'm go ahead so here we go this is a really slow one this is a five second pickup this two second one this is my read that I showed you earlier so let's find this okay here we go so between this function call Nano sleep and this function call access I should say system call sorry there is a five seconds of wall clock time roughly elapsed and that's because this system call Nano sleep looks like it's sleeping for five seconds so somewhere in the code path we've got an obnoxious five-second sleep now I admit this is a pretty contrived example normally when you're looking at the S trace output of a slow page load from an Apache worker process you're not going to see a developer put in a five-second sleep just to make the page load slowly the kinds of things they're going to slow down Apache normally in a page load from something like WordPress are things like a let's say a DNS lookup could be slow sometimes those timeout and can take several seconds to timeout that can cause slowness in a page load often I see a third-party RSS feed attached to a page take some time and that can add to a page load as well so bear with me that this example is a bit contrived but I think you'll learn something so here we have our Nano sleep and you can see as trace is trying to show us the arguments to nano sleep and in this case it's inside of curly braces now that means that the argument is a structure or a pointer to a structure and we can verify that so what we'll do is we'll go check out the old man page on then asleep and you can see that the first argument is a pointer to a time spec structure so s trace is smart enough to know what a time spec structure looks like or at least to break down a few of the arguments though I'm not sure with the sec argument or the second element in the time spec structure is but I have a feeling the first one is how many seconds to sleep so it's kind of cool that S traces a little bit smart and it can make some sense out of some of the arguments so we've seen how s trace with the dash R option can show us the relative times between system calls and it can help us locate where in the program things are getting slow so in this case we've identified a slow system call nano sleep just causing us problems so what we're going to do now is we're going to see if s trace can help us identify how this sleep is getting into our page so what we're going to do is we're going to reverse search and we're going to look for sleep and maybe it appears elsewhere in the s trace output and it looks like it does so this is let's get a full window here this is what looks like the results of a large read and this is where the 4k string size comes in handy because we might not have seen this with the default string size it would have just truncated some of what it read because it you know didn't want to show you the whole thing so here we see hello world backslash R backslash n and this looks awfully suspicious a little embedded PHP sleep 5 that looks very much like our man so what is this let's take a look aha so this is the results of a read like I thought and right above this read there's a right and we're doing a select yada yada WP post star from WP posts so this is where the code pulls your post from the database and it writes the query and it receives the results what is file descriptor 11 that's that's a good question let's search backwards for equals oops search backwards for equals 11 so that is aren't it aha here we go so we see socket PF files lock stream then little later it connects the socket to a UNIX domain socket minus QL dot sock now you use that internal UNIX domain socket when you're talking on the same machine as the my sequel daemon which we are in this case so this is been spying on Apache and PHP with s trace and I hope you've enjoyed watching thanks

Channel: spudlyo

Views: 22,855

Keywords: linux, apache, php, strace

Id: eF-p--AH37E

Length: 15min 0sec (900 seconds)

Published: Tue Mar 15 2011

Reddit Comments

[u/Pepser]

I do the same thing with a slight twist: ~> strace /usr/bin/php5 filename.php | less -S

This allows me to check on a per file basis where the delay's are happening.

[u/mod_a]

Thanks for this, very nice video. There were a few things you did that I don't know how to do.

• How did you get the dialog of screens to select from to show up?

• How were you searching your bash history?

• How were you searching in man?

• How did you delete everything after the cursor?

Thanks!

[u/DaveChild]

I had a quick go at this, but apache doesn't wait long enough for me to type commands in, get the pid, set up strace and finish the page request. Does anyone know where the wait is defined in apache? I set my timeout to 30 seconds and keepalive to 20 to see if that helped but it made no difference.

[u/freexe]

I think this video is great, but wouldn't it be better to use something like xdebug and kcachegrind to debug problems like that? It will give you a much better breakdown of slow running scripts.

[u/sionide21]

TIL about the pidof command! That will save me some ridiculous ps | grep |cut garbage.

[u/clearlight]

Strace helped me debug a php/apache segmentation fault recently, showed the SQL leading to the seg fault. It's a useful tool.

[u/solid7]

I know this was posted to /r/linux, but you might also look at dtrace, ktrace or truss depending on what you are running on.

[u/ahyes]

Strace is very useful. Last week we had a system that was hacked, and a few backdoors were thrown into place. While the attackers did backdoor a number of local binaries (mainly just sshd, and apache), they forgot about strace. A lot of useful information about how how sshd was backdoored was gleamed from stracing the sshd process, and setting up strace to track the subprocesses as well.. Pretty bizarre, ended up finding that whenever anyone logged in to ssh successfully, the login information for the account was passed off to a remote server in russia. Recovery of sshd was as easy as yum reinstall openssh-server; /etc/init.d/sshd restart.