Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

passenger_request_buffering off corrupts request body #2575

Open
thedanbob opened this issue Nov 19, 2024 · 0 comments
Open

passenger_request_buffering off corrupts request body #2575

thedanbob opened this issue Nov 19, 2024 · 0 comments

Comments

@thedanbob
Copy link

thedanbob commented Nov 19, 2024

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.

@thedanbob thedanbob changed the title passenger_request_buffering off corrupts file uploads passenger_request_buffering off corrupts request body Nov 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant