passenger: Passenger should not process requests from clients that have disconnected before the request is routed to an application processes
Passenger 5.0.4 stays blocked for minutes after a request storm while the log fills up with:
Disconnecting client with error: client socket write error: Broken pipe (errno=32)
This fact can easily be used for a denial of service:
# baseline response time (simulated slow endpoint)
curl -sw ' time_total: %{time_total}s\n' localhost:3000
YdxtDssIUc9zMl6UeGMncA== time_total: 10,007s
# hit passenger with lots of request that time out
wrk -c100 -d10s http://localhost:3000/
Running 10s test @ http://localhost:3000/
2 threads and 100 connections
1 requests in 10.02s, 286.00B read
Socket errors: connect 0, read 0, write 0, timeout 374
# now try another request
curl -sw ' time_total: %{time_total}s\n' localhost:3000
7ypBhdFvn1Wpwo6Q6mtaOA== time_total: 992,797s
By looking at the passenger log, it is evident that passenger is blocked processing all the requests made by clients that are no longer connected:
passenger start -e production --min-instances 1 --max-pool-size 1 --engine nginx
=============== Phusion Passenger Standalone web server started ===============
PID file: /home/felix/rack-hello/passenger.3000.pid
Log file: /home/felix/rack-hello/passenger.3000.log
Environment: production
Accessible via: http://0.0.0.0:3000/
You can stop Phusion Passenger Standalone by pressing Ctrl-C.
Problems? Check https://www.phusionpassenger.com/documentation/Users%20guide%20Standalone.html#troubleshooting
===============================================================================
App 62016 stdout:
App 62032 stdout:
[ 2015-03-13 10:10:16.8570 61985/7fa8b06c0700 Ser/Server.h:894 ]: [Client 1-1] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
[ 2015-03-13 10:11:24.1558 61985/7fa8b06c0700 Ser/Server.h:894 ]: [Client 1-5] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
[ 2015-03-13 10:11:34.1575 61985/7fa8b06c0700 Ser/Server.h:894 ]: [Client 1-6] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
[ 2015-03-13 10:11:44.1600 61985/7fa8b06c0700 Ser/Server.h:894 ]: [Client 1-7] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
…
[ 2015-03-13 10:27:34.4088 61985/7fa8b06c0700 Ser/Server.h:894 ]: [Client 1-101] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
[ 2015-03-13 10:27:44.4121 61985/7fa8b06c0700 Ser/Server.h:894 ]: [Client 1-100] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
[ 2015-03-13 10:28:04.4202 61985/7fa8b06c0700 Ser/Server.h:894 ]: [Client 1-105] Disconnecting client with error: client socket write error: Broken pipe (errno=32)
The problem here is that passenger detects client timeouts only after the processing of the app response is finished although the client might have disconnected before the request even left the request queue.
Todo list:
- Implement request queuing timeout
- Rename max_request_time to max_response_time
- Documentation
About this issue
- Original URL
- State: open
- Created 9 years ago
- Comments: 20 (9 by maintainers)
Hm, you are right. The passenger_max_request_time timer starts after a process has been selected for routing, not before.
Now that I think about it, ‘max request time’ may not be the right terminology. The current implementation is more like a ‘max response time’.
We should have another timeout that also applies to the queuing.
What is the best workaround for this issue? Faced with it on Nginx + Phusion Passenger 6.0.4 All instances stucks for hours and all with same error (passenger-status --show=server)
The client connection is closed before the request is done processing (errno=-1020)We have received a vote from an Enterprise customer for this feature. His use case is that they’re getting traffic too quickly, so their requests are filling up in the queue. But his case is not so much that clients abort the connection (causing Passenger to process work that is already gone), but rather that he doesn’t want clients to wait too long in the queue. I’ve split his issue into a separate ticket: #1688
We’ve recently had a discussion with an Enterprise customer about a similar problem. They are on Heroku, and whenever they deploy a new version, Heroku would spin up an instance, start Passenger and immediately direct traffic to that instance. This customer gets so much traffic, and spawning their app takes such a long time, that during the first minute or so their request queue would grow beyond the queue size.
Assuming that their clients disconnect early because of the long response time, if we are able to check for a disconnection then it would partially solve his problem.
On a side note: I suppose that, while the first process is being spawned, it is acceptable for the queue to grow over its configured size. But special casing this is not easy.
I would call this neither a bug, nor expected behavior. I’m not really sure how to categorize this. It’s definitely unwanted, but it’s not caused by anything that’s Passenger’s fault.
What’s happening here is that wrk creates a lot of connections. For each connection, Passenger waits until there is a free application process, then forwards the request there.
But the only way to detect whether a client has disconnected, is by reading from its socket, or by writing to its socket. When Passenger has read the HTTP header and its corresponding body, it stops reading from the socket because any further data may belong to next pipelined request. Similarly, there’s not much Passenger can send to the client until an application process has become available for processing the request, and the application has generated a response.
The Unicorn author implemented a hack for this problem. There was an exchange on the Unicorn mailing list between Shopify and the Unicorn author, which documents the problem pretty well. Unicorn writes the string ‘HTTP’ to the socket before request processing actually begins. Then, when writing the response, it simply omits the ‘HTTP’ part of the response because it has already been written. Sometimes, writing ‘HTTP’ early on allows it to detect a disconnection. But as you have observed, it doesn’t always work.