passenger
passenger copied to clipboard
phusion
`passenger_request_buffering off` corrupts request body
Issue report
Question 1: What is the problem?
Setting the nginx option passenger_request_buffering off; corrupts requests larger than ~10 KB.
With that option set, nginx buffers the headers and first part of the request body in memory rather than a temporary file. After opening a connection to the Passenger socket, nginx sends all these initial buffers at once. However, if the request is big enough for the body to require more than a couple of buffers (e.g. a file upload), the first two buffers get duplicated when they are sent to Passenger. I believe the end of the body (overflow after Content-Length) gets discarded, but I'm not sure in what part of the stack. The result is a request body with the right size but corrupted contents.
Repo with a sample app and reproduction steps: https://github.com/thedanbob/passenger-bug
Sample nginx debug logs:
2024/11/19 18:47:36 [debug] 37#37: accept on 0.0.0.0:8081, ready: 0
2024/11/19 18:47:36 [debug] 37#37: posix_memalign: 00005C5FCE350950:512 @16
2024/11/19 18:47:36 [debug] 37#37: *1 accept: 172.17.0.1:47812 fd:9
2024/11/19 18:47:36 [debug] 37#37: *1 event timer add: 9: 60000:531167419
2024/11/19 18:47:36 [debug] 37#37: *1 reusable connection: 1
2024/11/19 18:47:36 [debug] 37#37: *1 epoll add event: fd:9 op:1 ev:80002001
2024/11/19 18:47:36 [debug] 37#37: *1 http wait request handler
2024/11/19 18:47:36 [debug] 37#37: *1 malloc: 00005C5FCE3531A0:1024
2024/11/19 18:47:36 [debug] 37#37: *1 recv: eof:0, avail:-1
2024/11/19 18:47:36 [debug] 37#37: *1 recv: fd:9 1024 of 1024
2024/11/19 18:47:36 [debug] 37#37: *1 recv: avail:15525
2024/11/19 18:47:36 [debug] 37#37: *1 reusable connection: 0
2024/11/19 18:47:36 [debug] 37#37: *1 posix_memalign: 00005C5FCE3E4930:4096 @16
2024/11/19 18:47:36 [debug] 37#37: *1 http process request line
2024/11/19 18:47:36 [debug] 37#37: *1 http request line: "POST /16kb_unbuf.txt HTTP/1.1"
2024/11/19 18:47:36 [debug] 37#37: *1 http uri: "/16kb_unbuf.txt"
2024/11/19 18:47:36 [debug] 37#37: *1 http args: ""
2024/11/19 18:47:36 [debug] 37#37: *1 http exten: "txt"
2024/11/19 18:47:36 [debug] 37#37: *1 posix_memalign: 00005C5FCE3FB920:4096 @16
2024/11/19 18:47:36 [debug] 37#37: *1 http process request header line
2024/11/19 18:47:36 [debug] 37#37: *1 http header: "Host: localhost:8081"
2024/11/19 18:47:36 [debug] 37#37: *1 http header: "User-Agent: curl/8.11.0"
2024/11/19 18:47:36 [debug] 37#37: *1 http header: "Accept: */*"
2024/11/19 18:47:36 [debug] 37#37: *1 http header: "Content-Length: 16384"
2024/11/19 18:47:36 [debug] 37#37: *1 http header: "Content-Type: application/x-www-form-urlencoded"
2024/11/19 18:47:36 [debug] 37#37: *1 http header done
2024/11/19 18:47:36 [debug] 37#37: *1 event timer del: 9: 531167419
2024/11/19 18:47:36 [debug] 37#37: *1 generic phase: 0
2024/11/19 18:47:36 [debug] 37#37: *1 rewrite phase: 1
2024/11/19 18:47:36 [debug] 37#37: *1 using configuration ""
2024/11/19 18:47:36 [debug] 37#37: *1 http cl:16384 max:1048576
2024/11/19 18:47:36 [debug] 37#37: *1 rewrite phase: 3
2024/11/19 18:47:36 [debug] 37#37: *1 post rewrite phase: 4
2024/11/19 18:47:36 [debug] 37#37: *1 generic phase: 5
2024/11/19 18:47:36 [debug] 37#37: *1 generic phase: 6
2024/11/19 18:47:36 [debug] 37#37: *1 generic phase: 7
2024/11/19 18:47:36 [debug] 37#37: *1 access phase: 8
2024/11/19 18:47:36 [debug] 37#37: *1 access phase: 9
2024/11/19 18:47:36 [debug] 37#37: *1 access phase: 10
2024/11/19 18:47:36 [debug] 37#37: *1 post access phase: 11
2024/11/19 18:47:36 [debug] 37#37: *1 generic phase: 12
2024/11/19 18:47:36 [debug] 37#37: *1 generic phase: 13
2024/11/19 18:47:36 [debug] 37#37: *1 add cleanup: 00005C5FCE3E57C8
2024/11/19 18:47:36 [debug] 37#37: *1 http client request body preread 859
2024/11/19 18:47:36 [debug] 37#37: *1 http request body content length filter
2024/11/19 18:47:36 [debug] 37#37: *1 http body new buf t:1 f:0 00005C5FCE353245, pos 00005C5FCE353245, size: 859 file: 0, size: 0
2024/11/19 18:47:36 [debug] 37#37: *1 malloc: 00005C5FCE3E0710:8192
2024/11/19 18:47:36 [debug] 37#37: *1 http read client request body
2024/11/19 18:47:36 [debug] 37#37: *1 recv: eof:0, avail:15525
2024/11/19 18:47:36 [debug] 37#37: *1 recv: fd:9 8192 of 8192
2024/11/19 18:47:36 [debug] 37#37: *1 recv: avail:7333
2024/11/19 18:47:36 [debug] 37#37: *1 http client request body recv 8192
2024/11/19 18:47:36 [debug] 37#37: *1 http body new buf t:1 f:0 00005C5FCE3E0710, pos 00005C5FCE3E0710, size: 8192 file: 0, size: 0
2024/11/19 18:47:36 [debug] 37#37: *1 http init upstream, client timer: 0
2024/11/19 18:47:36 [debug] 37#37: *1 epoll add event: fd:9 op:3 ev:80002005
2024/11/19 18:47:36 [debug] 37#37: *1 post event 00005C5FCE3E9AF0
2024/11/19 18:47:36 [debug] 37#37: *1 posix_memalign: 00005C5FCE3E2720:4096 @16
2024/11/19 18:47:36 [debug] 37#37: *1 http cleanup add: 00005C5FCE3E2740
2024/11/19 18:47:36 [debug] 37#37: *1 get rr peer, try: 1
2024/11/19 18:47:36 [debug] 37#37: *1 stream socket 10
2024/11/19 18:47:36 [debug] 37#37: *1 epoll add connection: fd:10 ev:80002005
2024/11/19 18:47:36 [debug] 37#37: *1 connect to unix:/passenger_core, fd:10 #2
2024/11/19 18:47:36 [debug] 37#37: *1 connected
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream connect: 0
2024/11/19 18:47:36 [debug] 37#37: *1 posix_memalign: 00005C5FCE34D140:128 @16
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream send request
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream send request body
### ISSUE HAPPENS HERE ###
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:0 s:1180
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:859
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:8192
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:859
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:8192
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer in: 00005C5FCE3E27D0
2024/11/19 18:47:36 [debug] 37#37: *1 writev: 19282 of 19282
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer out: 0000000000000000
2024/11/19 18:47:36 [debug] 37#37: *1 http read client request body
2024/11/19 18:47:36 [debug] 37#37: *1 recv: eof:0, avail:7333
2024/11/19 18:47:36 [debug] 37#37: *1 recv: fd:9 7333 of 7333
2024/11/19 18:47:36 [debug] 37#37: *1 recv: avail:0
2024/11/19 18:47:36 [debug] 37#37: *1 http client request body recv 7333
2024/11/19 18:47:36 [debug] 37#37: *1 http body new buf t:1 f:0 00005C5FCE3E0710, pos 00005C5FCE3E0710, size: 7333 file: 0, size: 0
2024/11/19 18:47:36 [debug] 37#37: *1 http client request body rest 0
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:7333
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer in: 00005C5FCE3E5920
2024/11/19 18:47:36 [debug] 37#37: *1 writev: 7333 of 7333
2024/11/19 18:47:36 [debug] 37#37: *1 chain writer out: 0000000000000000
2024/11/19 18:47:36 [debug] 37#37: *1 event timer add: 10: 12000000:543107420
2024/11/19 18:47:36 [debug] 37#37: *1 http finalize request: -4, "/16kb_unbuf.txt?" a:1, c:2
2024/11/19 18:47:36 [debug] 37#37: *1 http request count:2 blk:0
2024/11/19 18:47:36 [debug] 37#37: *1 delete posted event 00005C5FCE3E9AF0
2024/11/19 18:47:36 [debug] 37#37: *1 http run request: "/16kb_unbuf.txt?"
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream check client, write event:0, "/16kb_unbuf.txt"
2024/11/19 18:47:36 [debug] 37#37: *1 http run request: "/16kb_unbuf.txt?"
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream check client, write event:1, "/16kb_unbuf.txt"
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream request: "/16kb_unbuf.txt?"
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream dummy handler
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream request: "/16kb_unbuf.txt?"
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream dummy handler
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream request: "/16kb_unbuf.txt?"
2024/11/19 18:47:36 [debug] 37#37: *1 http upstream process header
2024/11/19 18:47:36 [debug] 37#37: *1 malloc: 00005C5FCE357E70:16384
2024/11/19 18:47:36 [debug] 37#37: *1 recv: eof:0, avail:-1
2024/11/19 18:47:36 [debug] 37#37: *1 recv: fd:10 150 of 16384
2024/11/19 18:47:36 [debug] 37#37: *1 HTTP/1.1 204 No Content
Connection: keep-alive
Status: 204 No Content
Date: Tue, 19 Nov 2024 18:47:36 GMT
X-Powered-By: Phusion Passenger(R) 6.0.23
Server: nginx/1.22.1 + Phusion Passenger(R) 6.0.23
At the indicated place above five buffers get written, corresponding to the request headers (rewritten with Passenger annotations) and the first two request body buffers, twice. This can be confirmed by using strace on the nginx worker (relevant section formatted for clarity):
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 http upstream connect: 0\n", 63) = 63
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 posix_memalign: 00005C5FCE"..., 79) = 79
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 http upstream send request"..., 65) = 65
getsockopt(10, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 http upstream send request"..., 70) = 70
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:0 s:11"..., 67) = 67
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:85"..., 66) = 66
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:81"..., 67) = 67
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:85"..., 66) = 66
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 chain writer buf fl:1 s:81"..., 67) = 67
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 chain writer in: 00005C5FC"..., 72) = 72
writev(10, [
{iov_base="POST /16kb_unbuf.txt HTTP/1.1\r\nConnection: close\r\nHost: localhos"..., iov_len=1180},
{iov_base="01 0000000000000000000000000000000000000000000000000000000000000"..., iov_len=859},
{iov_base="0000000000000000000000000000000000000000000000000000000000000000"..., iov_len=8192},
{iov_base="01 0000000000000000000000000000000000000000000000000000000000000"..., iov_len=859},
{iov_base="0000000000000000000000000000000000000000000000000000000000000000"..., iov_len=8192}
], 5) = 19282
gettid() = 37
write(3, "2024/11/19 18:47:36 [debug] 37#37: *1 writev: 19282 of 19282\n", 61) = 61
It can also be confirmed by inspecting the resulting file.
Question 2: Passenger version and integration mode: Open source Passenger 6.0.23/nginx 1.22.1
Question 3: OS or Linux distro, platform (including version): Debian 12, x86_64
Question 4: Passenger installation method: Phusion APT repo
Question 5: Your app's programming language (including any version managers) and framework (including versions): Ruby 3.1 / rack 3.1.8 (sample app) and ruby 3.3.6 / rails 8.0 (production)
Question 6: Are you using a PaaS and/or containerization? If so which one? Docker (sample app) and Debian 12 VM (production).
Question 7: Anything else about your setup that we should know? Once or twice the problem seemed to resolve after restarting nginx during troubleshooting, so it might not be entirely deterministic.
@CamJN This relates to the Nginx upstream system's request buffering mechanism. It's possible that we are using that mechanism incorrectly. You can look at how ngx_http_proxy_module or ngx_http_scgi_module uses it.
