[ScottHelme] Sockets - Under The Hood: Understanding Truncated Request Behaviour #20117
Labels
Comments
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
I'm thoroughly pleased to be able to say that I finally understand the issue that's been bothering me on Report URI for a few weeks now, and this is the blog post that's going to explain everything!
Report URI
If you haven't read the first two blog posts related to this issue, it might help you to get some background on what I'm going to be talking about here:
Unravelling The Mystery Of Truncated POST Requests On Report URI
Processing Truncated Requests? A PHP Debugging Deep Dive
This weird behaviour of our application receiving and then trying to process truncated POST requests has lead me on quite a journey of learning, and I can finally explain what's happening!
The Story So Far
In the previous blog posts, I'd narrowed it down to what was happening, but not why it was happening, and I was still stumped. After patching PHP, I could see it was calling
read()on the socket and reading until0was returned, but0was being returned before expected. Here's the log of the behaviour from the previous blog post.I knew that Nginx was receiving the full request, so the problem was happening in the
fastcgi_passto PHP-FPM, but I couldn't wrap my head around the circumstances. I wanted to understand more on the underlying mechanics of how Nginx was talking to PHP and, more specifically, what was failing in that process.bpftrace
In the last blog I had to get familiar with
stracefor the first time, and this time around, I'd asked for some assistance from Ignat Korchagin who kindly whipped up severalbpftracecommands, and, could also reliably reproduce the issue. Hopefully, by monitoring things a little more closely between Nginx and PHP, I could gain an understanding of precisely what was happening.After monitoring my test server when the issue was happening, I could see Nginx hitting
EAGAIN( source.-,EAGAIN,-Resource%20temporarily%20unavailable)) when trying to write to the socket, and I could see PHP gettingEPIPE( source when trying to read from the socket, but it still wasn't clear to me how that was occurring. TheEAGAINerror is likely because the socket buffer is full when Nginx is sending, so it can't send any more data, and theEPIPEcomes when PHP tries to read from the socket that has since been closed by Nginx. Here's the command.$ bpftrace -e 'kretfunc:unix_stream_sendmsg /retval < 0/ { printf("%d\n", retval); }' Attaching 1 probe... -11 -11 [-11 repeated 20x] -11 -11 -32 -32 [-32 repeated 12x] -32 -32The log reads like Nginx is trying to write to the socket which has a full buffer, and PHP is trying to read from a socket that's closed, but if PHP has called
accept(), why would it not be able toread()? Theaccept()call is followed byread()calls in the PHP source almost immediately so it didn't make sense. I also saw 12xEPIPE (-32)errors coming from PHP and I had exactly 12x truncated payload errors insyslogusing the same logging from the previous blog post.Digging a little deeper, I wanted to see when the calls to
connect()andaccept()were being made.$ bpftrace -e 'tracepoint:syscalls:sys_enter_connect /comm == "nginx"/ { printf("connect: %s\n", strftime("%H:%M:%S:%f", nsecs)); } tracepoint:syscalls:sys_enter_accept /comm == "php-fpm8.2"/ { printf("accept: %s\n", strftime("%H:%M:%S:%f", nsecs)); }'After firing another batch of 20 requests, I could see all of the
connect()calls from nginx happen right away, but theaccept()calls from PHP were much more spaced out.I still wasn't clear on how this was working because PHP is calling
accept()andread()very close together, so if PHP can accept, why is the read failing with a partial payload?!The truncated payload issued showing in
syslogmatched up to the lateaccept()calls from PHP! It was at this point I was prompted to look at thebacklogparameter oflisten()and it became clear that this behaviour can be explained bybacklog, something I wasn't familiar with.int listen(int sockfd , int backlog );
When calling
listen(), the second parameter provided isbacklog, which is described as follows in the docs:So now we can have an application, like Nginx, call
connect()and succeed but without the application on the other side, PHP, callingaccept()! This is finally starting to make a little more sense with the behaviour I'm seeing. It also turns out that Nginx canwrite()until the receive buffer on the socket is full, and that is when it's going to hitEAGAIN. I confirmed this usingstrace:I believe that Nginx is using
writev()to send thefastcgiheaders, and usingsendfile()to send chunks of the body, which comes from this function in the code. It certainly seems like this is starting to make a little sense. Looking at the PHP config, I wanted to see what the backlog value was because it's not something I ever recall setting. I found the following in our config:With a default value of
-1, I was guessing thatbacklogmight be cast to an unsigned int by the kernel, which it is ( source).You can also see that, as stated in the manual ( source), if the defined
backlogvalue is greater thansomaxconn, it will be silently truncated to that value. Because-1will actually be4294967295, by default, PHP will always set backlog to the value ofsomaxconn, effectively letting the system decide.# cat /proc/sys/net/core/somaxconn 4096This means we can have up to 4,096 connections pending in the backlog queue, which is quite a few!
The Theory
At this point, I believe something like the following is happening during the lifecycle of the request.
connect()syscall and begins writing to the socket.EAGAINand likely wait for something likefastcgi_send_timeout( source).EPIPEand process the content read from the buffer.Sounds logical, right? It should also be easy enough to test this now that I know what I'm aiming for so I tinkered with some of the config parameters in Nginx and it did indeed seem
fastcgi_send_timeoutwas the main factor. By reducing the send timeout, I would see more requests failing to parse in general, and I assume that's because Nginx is timing out sooner so PHP has less time to get to thebacklog.Testing The Theory!
Now for the fun part, where you actually find out if you were right, or you were completely off the mark! I was looking into ways that I could reliably reproduce this and my first effort was to take a few steps. I reduced the number of child processes PHP can spawn to one, so it would be easy to keep it busy, and I reduced the send timeout on Nginx to three seconds so it would time out very quickly. With this basic setup I could send two requests sequentially and the first one would succeed and the second one would reliably fail, 100% of the time. I wanted something better than that though, something that would allow me to trigger this on a single request, and that's when João Poupino dropped this little gem in Slack!
This gives me the ability to talk directly to the PHP socket, using the FastCGI protocol, and completely cut Nginx out of the equation. The script also has a feature that allows you to send only a partial request, where it will randomly
close()the socket somewhere during the transmission of the payload. With this, it should now be possible to reproduce this problem with only a single request. The moment of truth....The script started to send my large POST payload and decided to close the socket after sending only 24 out of the 37 chunks of the request. Time to check
syslogand see if we can find what I'm hoping for and expecting.Finally! 🍾🥂
It feels awesome to get to the bottom of something that's been bugging you so much! I fixed the issue a whole two blog posts ago, and I could have moved on, but sometimes, I really just need to understand why something is happening, and honestly, it was quite a fun journey getting here. I owe a big thanks to João and Ignat, who collectively must have saved me countless days of effort that I might not even have had time for.
I've also skipped over a few of the debugging steps above because this was becoming another lengthy blog post, but I did, during and after debugging, spend a lot of time trawling through the Nginx source to understand fully what's happening and also just to confirm my understanding.
The Nginx behaviour of using
writev()andsendfile()can be seen here: https://github.com/nginx/nginx/blob/9f8d60081cd4eefa5fcf0df275d784d621290b9b/src/os/unix/ngx_linux_sendfile_chain.c#L50Nginx adds a timeout when receiving
EAGAINhere, usingfastcgi_send_timeout. I also noticed in the Nginx source that it makes use ofepoll(), which explains earlier why I was only seeing a singleEAGAINper request: https://github.com/nginx/nginx/blob/9f8d60081cd4eefa5fcf0df275d784d621290b9b/src/http/ngx_http_upstream.c#L2093The event timer expires in Nginx here: https://github.com/nginx/nginx/blob/9f8d60081cd4eefa5fcf0df275d784d621290b9b/src/event/ngx_event_timer.c#L54
I also spotted that PHP was respawning the child processes when I was testing and that they'd always have new PIDs after a test run. It seems that if the child is idle for too long, PHP will kill and respawn it, possibly based on this timeout value: https://github.com/php/php-src/blob/47c6b3bd452d2932af5c2f021b10ab2aaed01fb1/sapi/fpm/fpm/fpm_conf.c#L622
All in all, I can now say I'm happy that I understand everything that was happening with this issue and can finally put it to bed!
As a final closing note, just to nicely close things off, I got a response on the PHP bug that I filed in the previous blog post and it seems that this finding is indeed a bug and will be patched!
https://scotthelme.co.uk/sockets-under-the-hood/
The text was updated successfully, but these errors were encountered: