request->request_body->bufs
. What I did not tell you is what is in there and why there is more than one buffer. It all boils down to the fact that nginx tries to have the most minimal impact on the planet by saving resources and doing as little as it can. That plus the fact that the network does pretty much what it wants.To make my point as clear as I can I decided to walk you through an example of what happens when you force the network to do things unnatural. To do so, I wrote a test case:
def test_POST_show_buffers(self): conn = httplib.HTTPConnection("localhost", 8000, None, 20) params = urllib.urlencode({'value' : 'N:12345:678'+'678'*300}) conn.putrequest("POST", "/tutu") conn.putheader('Content-Type', "application/x-www-form-urlencoded") conn.putheader('Content-Length', str(len(params))) conn.putheader('Accept', "text/plain") conn.endheaders() conn.send(params[0:6]) time.sleep(1) conn.send(params[6:15]) time.sleep(1) conn.send(params[15:]) response = conn.getresponse() self.assertEqual(response.status, 200) data = response.read(); conn.close() self.assertNotRegexpMatches(data, "Robin");You got the idea: I want to send the body
value=N:12345:678678678...
with 678 being repeated 301 times (that's actually value=N%3A12345%3A678678678...
after encoding the parameters) in three parts with a little pause between them to make sure the network layer sends them separately.- First part is
value=
and goes with the headers - Second part is
N%3A12345
- Third and last part is
N%3A678678678...
My nginx being configured with maximum logging (i.e.
error_log logs/error.log debug;
), I'll walk you through the interesting parts of the log...22:16:20 [debug] 5222#0: *22 accept: 127.0.0.1 fd:3nginx accepted the connection. Note the *22 which is an identifier assigned to this connection. This is what you'll use to keep track of what's going on for this customer in the rest of the log. This is very convenient. I guess Igor coming from a sysadmin background thought of making sysadmins' lives easier, a thing developers tend not to do (as a counterpart, he did not make developers' lives easier but that's another story). So, with this *22 we look a bit further:
22:16:20 [debug] 5222#0: *22 http process request line 22:16:20 [debug] 5222#0: *22 recv: fd:3 168 of 1024 22:16:20 [debug] 5222#0: *22 http request line: "POST /tutu HTTP/1.1" 22:16:20 [debug] 5222#0: *22 http uri: "/tutu" 22:16:20 [debug] 5222#0: *22 http args: "" 22:16:20 [debug] 5222#0: *22 http exten: "" 22:16:20 [debug] 5222#0: *22 http process request header line 22:16:20 [debug] 5222#0: *22 http header: "Host: localhost:8000" 22:16:20 [debug] 5222#0: *22 http header: "Accept-Encoding: identity" 22:16:20 [debug] 5222#0: *22 http header: "Content-Type: application/x-www-form-urlencoded" 22:16:20 [debug] 5222#0: *22 http header: "Content-Length: 921" 22:16:20 [debug] 5222#0: *22 http header: "Accept: text/plain" 22:16:20 [debug] 5222#0: *22 http header doneAnd we see that nginx read 168 bytes (for those of you who don't know, recv is the system call to read data from a file descriptor: file descriptor 3 in our case which is the one for the socket resulting of the accept system call we saw earlier). 168 bytes were enough to get the request line plus all the headers. Now, looking even further, we find:
22:16:20 [debug] 5222#0: *22 http client request body preread 6 22:16:20 [debug] 5222#0: *22 http read client request body 22:16:20 [debug] 5222#0: *22 recv: fd:3 -1 of 915 22:16:20 [debug] 5222#0: *22 recv() not ready (11: Resource temporarily unavailable) 22:16:20 [debug] 5222#0: *22 http client request body recv -2 22:16:20 [debug] 5222#0: *22 http client request body rest 915nginx knows it has already read 6 bytes. Which is exactly the size of the first part of the body (
value=
). And, as you can see it knows that it still needs 915 more bytes to read the rest of the body. This is when it figures out that it won't be able to fit the rest of the 1024 buffer it allocated for processing the request line plus its headers. But it would be a shame to throw away all this good memory. So, it keeps the first 6 bytes as the first buffer for the request body and creates a new one for the remaining 915 bytes. A bit later:22:16:21 [debug] 5222#0: *22 http run request: "/tutu?" 22:16:21 [debug] 5222#0: *22 http read client request body 22:16:21 [debug] 5222#0: *22 recv: fd:3 9 of 915 22:16:21 [debug] 5222#0: *22 http client request body recv 9 22:16:21 [debug] 5222#0: *22 http client request body rest 906This little web server is good at math: it received the second part (9 bytes), copied them in the second buffer and knows that it needs only 906 more to be done. And finally:
22:16:22 [debug] 5222#0: *22 http run request: "/tutu?" 22:16:22 [debug] 5222#0: *22 http read client request body 22:16:22 [debug] 5222#0: *22 recv: fd:3 906 of 906 22:16:22 [debug] 5222#0: *22 http client request body recv 906 22:16:22 [debug] 5222#0: *22 http client request body rest 0We are done. And with your favorite debugger you can see that for once
request->request_body->bufs
is not NULL
.As you noticed, I had to go through quite some effort to exercise this situation, but it can happen. And it gave me an opportunity to walk you through some logging...
No comments:
Post a Comment