plans for chunked encoding

Fri Nov 23 09:19:32 UTC 2012

Hi Maxim,

On Fri, Nov 23, 2012 at 06:21:20AM +0400, Maxim Dounin wrote:
> > > > $ curl -v -X POST -d "@/dev/null" --header "Transfer-Encoding: chunked" http://127.0.0.1:80/
> > > > 
> > > > Returns 404 in headers but 500 in html body. Is this how it's supposed to be ?
> > 
> > ...
> > 
> > > If you indeed see 500 in body it might be something to do with 
> > > either your module or nginx config you use.
> > 
> > Here is full information from my side... First the nginx logs:
> > 
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 http cl:-1 max:1048576
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 rewrite phase: 2
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 post rewrite phase: 3
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 generic phase: 4
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 generic phase: 5
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 access phase: 6
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 post access phase: 7
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 content phase: 8
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 open index "/etc/nginx/html/index.html"
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 stat() "/etc/nginx/html/index.html" failed (2: No such file or directory)
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 http index check dir: "/etc/nginx/html"
> > 2012/11/22 21:46:00 [error] 1237#0: *1 "/etc/nginx/html/index.html" is not found (2: No such file or directory), client: 127.0.0.1, server: , request: "POST / HTTP/1.1", host: "127.0.0.1"
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 http finalize request: 404, "/?" a:1, c:1
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 http special response: 404, "/?"
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 http set discard body
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 http chunked byte: 0D s:0
> > 2012/11/22 21:46:00 [error] 1237#0: *1 client sent invalid chunked body, client: 127.0.0.1, server: , request: "POST / HTTP/1.1", host: "127.0.0.1"
> > 2012/11/22 21:46:00 [debug] 1237#0: *1 HTTP/1.1 404 Not Found^M
> > Server: nginx/1.3.9^M
> > Date: Thu, 22 Nov 2012 20:46:00 GMT^M
> > Content-Type: text/html^M
> > Content-Length: 192^M
> > Connection: keep-alive^M
> > Keep-Alive: timeout=130^M
> 
> [...]
> 
> Ok, I see what goes on.  In your case (likely due to different 
> curl version) request body is corrupted from start and nginx is 
> able to detect the corruption while discarding request body.
> 
> This results in 500 response body due to the followin code in 
> ngx_http_special_response_handler():
> 
>     if (ngx_http_discard_request_body(r) != NGX_OK) {
>         error = NGX_HTTP_INTERNAL_SERVER_ERROR;
>     }
> 
> Two patches below fixes this, as well as couple of other problems 
> with chunked body discarding identified while testing.

This is my curl version:

$ curl -V
curl 7.28.0 (x86_64-unknown-linux-gnu) libcurl/7.28.0 OpenSSL/1.0.1c zlib/1.2.7 libssh2/1.4.2
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp scp sftp smtp smtps telnet tftp 
Features: AsynchDNS IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP 

After applying your patches this is the result:

$ curl -v -X POST -d "@/dev/null" --header "Transfer-Encoding: chunked" http://127.0.0.1:80/
* About to connect() to 127.0.0.1 port 80 (#0)
*   Trying 127.0.0.1...
* connected
* Connected to 127.0.0.1 (127.0.0.1) port 80 (#0)
> POST / HTTP/1.1
> User-Agent: curl/7.28.0
> Host: 127.0.0.1
> Accept: */*
> Transfer-Encoding: chunked
> Content-Type: application/x-www-form-urlencoded
> 
* upload completely sent off: 7 out of 0 bytes
< HTTP/1.1 400 Bad Request
< Server: nginx/1.3.9
< Date: Fri, 23 Nov 2012 09:14:15 GMT
< Content-Type: text/html
< Content-Length: 172
< Connection: close
< 
<html>
<head><title>400 Bad Request</title></head>
<body bgcolor="white">
<center><h1>400 Bad Request</h1></center>
<hr><center>nginx/1.3.9</center>
</body>
</html>
* Closing connection #0

And the nginx logs:

2012/11/23 10:14:08 [debug] 28084#0: epoll add event: fd:7 op:1 ev:00000001
2012/11/23 10:14:15 [debug] 28084#0: accept on 0.0.0.0:80, ready: 0
2012/11/23 10:14:15 [debug] 28084#0: posix_memalign: 0000000001618820:256 @16
2012/11/23 10:14:15 [debug] 28084#0: *1 accept: 127.0.0.1 fd:3
2012/11/23 10:14:15 [debug] 28084#0: *1 event timer add: 3: 60000:1353662115189
2012/11/23 10:14:15 [debug] 28084#0: *1 epoll add event: fd:3 op:1 ev:80000001
2012/11/23 10:14:15 [debug] 28084#0: *1 malloc: 000000000162B5E0:1272
2012/11/23 10:14:15 [debug] 28084#0: *1 posix_memalign: 0000000001618980:256 @16
2012/11/23 10:14:15 [debug] 28084#0: *1 malloc: 000000000162BAE0:1024
2012/11/23 10:14:15 [debug] 28084#0: *1 posix_memalign: 000000000163E490:4096 @16
2012/11/23 10:14:15 [debug] 28084#0: *1 http process request line
2012/11/23 10:14:15 [debug] 28084#0: *1 recv: fd:3 158 of 1024
2012/11/23 10:14:15 [debug] 28084#0: *1 http request line: "POST / HTTP/1.1"
2012/11/23 10:14:15 [debug] 28084#0: *1 http uri: "/"
2012/11/23 10:14:15 [debug] 28084#0: *1 http args: ""
2012/11/23 10:14:15 [debug] 28084#0: *1 http exten: ""
2012/11/23 10:14:15 [debug] 28084#0: *1 http process request header line
2012/11/23 10:14:15 [debug] 28084#0: *1 http header: "User-Agent: curl/7.28.0"
2012/11/23 10:14:15 [debug] 28084#0: *1 http header: "Host: 127.0.0.1"
2012/11/23 10:14:15 [debug] 28084#0: *1 http header: "Accept: */*"
2012/11/23 10:14:15 [debug] 28084#0: *1 http header: "Transfer-Encoding: chunked"
2012/11/23 10:14:15 [debug] 28084#0: *1 http header: "Content-Type: application/x-www-form-urlencoded"
2012/11/23 10:14:15 [debug] 28084#0: *1 http header done
2012/11/23 10:14:15 [debug] 28084#0: *1 event timer del: 3: 1353662115189
2012/11/23 10:14:15 [debug] 28084#0: *1 rewrite phase: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 test location: "/"
2012/11/23 10:14:15 [debug] 28084#0: *1 using configuration "/"
2012/11/23 10:14:15 [debug] 28084#0: *1 http cl:-1 max:1048576
2012/11/23 10:14:15 [debug] 28084#0: *1 rewrite phase: 2
2012/11/23 10:14:15 [debug] 28084#0: *1 http client request body preread 7
2012/11/23 10:14:15 [debug] 28084#0: *1 http request body chunked filter
2012/11/23 10:14:15 [debug] 28084#0: *1 http body chunked buf t:1 f:0 000000000162BAE0, pos 000000000162BB77, size: 7 file: 0, size: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 http chunked byte: 0D s:0
2012/11/23 10:14:15 [error] 28084#0: *1 client sent invalid chunked body, client: 127.0.0.1, server: , request: "POST / HTTP/1.1", host: "127.0.0.1"
2012/11/23 10:14:15 [debug] 28084#0: *1 http finalize request: 400, "/?" a:1, c:1
2012/11/23 10:14:15 [debug] 28084#0: *1 http special response: 400, "/?"
2012/11/23 10:14:15 [debug] 28084#0: *1 HTTP/1.1 400 Bad Request
Server: nginx/1.3.9
Date: Fri, 23 Nov 2012 09:14:15 GMT
Content-Type: text/html
Content-Length: 172
Connection: close

2012/11/23 10:14:15 [debug] 28084#0: *1 write new buf t:1 f:0 000000000163EE90, pos 000000000163EE90, size: 151 file: 0, size: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 http write filter: l:0 f:0 s:151
2012/11/23 10:14:15 [debug] 28084#0: *1 http output filter "/?"
2012/11/23 10:14:15 [debug] 28084#0: *1 http copy filter: "/?"
2012/11/23 10:14:15 [debug] 28084#0: *1 write old buf t:1 f:0 000000000163EE90, pos 000000000163EE90, size: 151 file: 0, size: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 write new buf t:0 f:0 0000000000000000, pos 00000000006780C0, size: 120 file: 0, size: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000677C60, size: 52 file: 0, size: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 http write filter: l:1 f:0 s:323
2012/11/23 10:14:15 [debug] 28084#0: *1 http write filter limit 0
2012/11/23 10:14:15 [debug] 28084#0: *1 writev: 323
2012/11/23 10:14:15 [debug] 28084#0: *1 http write filter 0000000000000000
2012/11/23 10:14:15 [debug] 28084#0: *1 http copy filter: 0 "/?"
2012/11/23 10:14:15 [debug] 28084#0: *1 http finalize request: 0, "/?" a:1, c:1
2012/11/23 10:14:15 [debug] 28084#0: *1 event timer add: 3: 5000:1353662060189
2012/11/23 10:14:15 [debug] 28084#0: *1 http lingering close handler
2012/11/23 10:14:15 [debug] 28084#0: *1 recv: fd:3 -1 of 4096
2012/11/23 10:14:15 [debug] 28084#0: *1 recv() not ready (11: Resource temporarily unavailable)
2012/11/23 10:14:15 [debug] 28084#0: *1 lingering read: -2
2012/11/23 10:14:15 [debug] 28084#0: *1 event timer: 3, old: 1353662060189, new: 1353662060189
2012/11/23 10:14:15 [debug] 28084#0: *1 http lingering close handler
2012/11/23 10:14:15 [debug] 28084#0: *1 recv: fd:3 0 of 4096
2012/11/23 10:14:15 [debug] 28084#0: *1 lingering read: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 http request count:1 blk:0
2012/11/23 10:14:15 [debug] 28084#0: *1 http close request
2012/11/23 10:14:15 [debug] 28084#0: *1 http log handler
2012/11/23 10:14:15 [debug] 28084#0: *1 free: 000000000163E490, unused: 922
2012/11/23 10:14:15 [debug] 28084#0: *1 close http connection: 3
2012/11/23 10:14:15 [debug] 28084#0: *1 event timer del: 3: 1353662060189
2012/11/23 10:14:15 [debug] 28084#0: *1 reusable connection: 0
2012/11/23 10:14:15 [debug] 28084#0: *1 free: 000000000162BAE0
2012/11/23 10:14:15 [debug] 28084#0: *1 free: 000000000162B5E0
2012/11/23 10:14:15 [debug] 28084#0: *1 free: 0000000001618820, unused: 8
2012/11/23 10:14:15 [debug] 28084#0: *1 free: 0000000001618980, unused: 128

Let me know if I need to test anything else.

Luka