Application sent EOF before finishing response headers resulting in 502

Question

We're running 2 Sinatra apps side-by-side on phusion passenger + nginx on an admittedly EOL version of ruby using the Docker image phusion/passenger-ruby27:2.5.0. We're using memcached-backed sessions using dalli

Sometimes a requests from both apps result in a 502 and logs show "Application sent EOF before finishing response headers."

We enabled the highest log level for passenger and see something like this:

[ D3 2023-08-04 18:48:09.5666 26/T9 age/Cor/Con/CheckoutSession.cpp:112 ]: [Client 2-3] Event: sessionCheckedOutFromAnotherThread

[ D 2023-08-04 18:48:09.5666 26/T9 age/Cor/Con/CheckoutSession.cpp:138 ]: [Client 2-3] Session checked out: pid=728, gupid=1ae1688-9o7lJQglk4

[ D2 2023-08-04 18:48:09.5666 26/T9 age/Cor/App/Gro/SessionManagement.cpp:150 ]: Session closed for process (pid=600, group=/home/app (production))

[ D3 2023-08-04 18:48:09.5666 26/T9 age/Cor/App/Socket.h:90 ]: Connecting to unix:/var/run/passenger-instreg/passenger.afaReFU/apps.s/ruby.2r1ia1AejvPHCqNjzs40Ker0r0uyrHKQ8MOcfrNtL

[ D3 2023-08-04 18:48:09.5667 26/T9 age/Cor/App/Socket.h:186 ]: Socket unix:/var/run/passenger-instreg/passenger.afaReFU/apps.s/ruby.2r1ia1AejvPHCqNjzs40Ker0r0uyrHKQ8MOcfrNtL: there are now 1 total connections

[ D 2023-08-04 18:48:09.5667 26/T9 age/Cor/Con/CheckoutSession.cpp:199 ]: [Client 2-3] Session initiated: fd=40

[ D2 2023-08-04 18:48:09.5667 26/T9 age/Cor/Con/SendRequest.cpp:87 ]: [Client 2-3] Sending headers to application with session protocol

[ D3 2023-08-04 18:48:09.5668 26/T9 age/Cor/Con/SendRequest.cpp:184 ]: [Client 2-3] Header data: "\000\000\001|REQUEST_URI\000/healthcheck\000PATH_INFO\000/healthcheck\000SCRIPT_NAME\000\000QUERY_STRING\000\000REQUEST_METHOD\000GET\000SERVER_NAME\00010.0.1.247\000SERVER_PORT\00065530\000SERVER_SOFTWARE\000nginx/1.18.0 Phusion_Passenger/6.0.18\000SERVER_PROTOCOL\000HTTP/1.1\000REMOTE_ADDR\00010.0.1.130\000REMOTE_PORT\00058222\000PASSENGER_CONNECT_PASSWORD\000X2uCYvmk9f5yK0Sv\000HTTP_USER_AGENT\000ELB-HealthChecker/1.0\000HTTP_ACCEPT\000*/*\000HTTP_HOST\00010.0.1.247:65530\000"

[ D2 2023-08-04 18:48:09.5668 26/T9 age/Cor/Con/SendRequest.cpp:938 ]: [Client 2-3] No body to send to application

[ D3 2023-08-04 18:48:09.5668 26/T9 age/Cor/Con/CheckoutSession.cpp:114 ]: [Client 2-3] Request refcount decreased; it is now 1

[ D3 2023-08-04 18:48:09.5679 26/T9 Ser/FdSourceChannel.h:55 ]: [Client 2-3] Request refcount increased; it is now 2

[ D3 2023-08-04 18:48:09.5681 26/T9 Ser/Channel.h:355 ]: [Client 2-3] Request refcount increased; it is now 3

[ D3 2023-08-04 18:48:09.5682 26/T9 age/Cor/Con/ForwardResponse.cpp:64 ]: [Client 2-3] Event: onAppSourceData

[ D 2023-08-04 18:48:09.5683 26/T9 age/Cor/Con/ForwardResponse.cpp:131 ]: [Client 2-3] Application sent EOF before finishing response headers

[ W 2023-08-04 18:48:09.5683 26/T9 age/Cor/Con/InternalUtils.cpp:96 ]: [Client 2-3] Sending 502 response: application did not send a complete response

[ D3 2023-08-04 18:48:09.5683 26/T9 Ser/FileBufferedChannel.h:1416 ]: [FBC 0x7f1a4c000d20] Feeding 223 bytes

[ D3 2023-08-04 18:48:09.5683 26/T9 Ser/FileBufferedChannel.h:486 ]: [FBC 0x7f1a4c000d20] pushBuffer() completed: nbuffers = 1, bytesBuffered = 223

[ D3 2023-08-04 18:48:09.5685 26/T9 Ser/FileBufferedChannel.h:554 ]: [FBC 0x7f1a4c000d20] Reader: reading next

[ D3 2023-08-04 18:48:09.5685 26/T9 Ser/FileBufferedChannel.h:586 ]: [FBC 0x7f1a4c000d20] Reader: found buffer, 223 bytes

[ D3 2023-08-04 18:48:09.5685 26/T9 Ser/FileBufferedChannel.h:493 ]: [FBC 0x7f1a4c000d20] popBuffer() completed: nbuffers = 0, bytesBuffered = 0

[ D3 2023-08-04 18:48:09.5685 26/T9 Ser/FileBufferedChannel.h:594 ]: [FBC 0x7f1a4c000d20] Reader: feeding buffer, 223 bytes

[ D3 2023-08-04 18:48:09.5686 26/T9 Ser/FileBufferedChannel.h:554 ]: [FBC 0x7f1a4c000d20] Reader: reading next

[ D3 2023-08-04 18:48:09.5686 26/T9 Ser/FileBufferedChannel.h:561 ]: [FBC 0x7f1a4c000d20] Reader: no more buffers. Transitioning to RS_INACTIVE

[ D3 2023-08-04 18:48:09.5686 26/T9 Ser/FileBufferedChannel.h:539 ]: [FBC 0x7f1a4c000d20] Calling dataFlushedCallback

[ D3 2023-08-04 18:48:09.5689 26/T9 Ser/FileBufferedChannel.h:1416 ]: [FBC 0x7f1a4c000d20] Feeding 54 bytes

[ D3 2023-08-04 18:48:09.5689 26/T9 Ser/FileBufferedChannel.h:486 ]: [FBC 0x7f1a4c000d20] pushBuffer() completed: nbuffers = 1, bytesBuffered = 54

[ D3 2023-08-04 18:48:09.5689 26/T9 Ser/FileBufferedChannel.h:554 ]: [FBC 0x7f1a4c000d20] Reader: reading next

[ D3 2023-08-04 18:48:09.5689 26/T9 Ser/FileBufferedChannel.h:586 ]: [FBC 0x7f1a4c000d20] Reader: found buffer, 54 bytes

[ D3 2023-08-04 18:48:09.5689 26/T9 Ser/FileBufferedChannel.h:493 ]: [FBC 0x7f1a4c000d20] popBuffer() completed: nbuffers = 0, bytesBuffered = 0

[ D3 2023-08-04 18:48:09.5689 26/T9 Ser/FileBufferedChannel.h:594 ]: [FBC 0x7f1a4c000d20] Reader: feeding buffer, 54 bytes

[ D3 2023-08-04 18:48:09.5690 26/T9 Ser/FileBufferedChannel.h:554 ]: [FBC 0x7f1a4c000d20] Reader: reading next

[ D3 2023-08-04 18:48:09.5690 26/T9 Ser/FileBufferedChannel.h:561 ]: [FBC 0x7f1a4c000d20] Reader: no more buffers. Transitioning to RS_INACTIVE

[ D3 2023-08-04 18:48:09.5690 26/T9 Ser/FileBufferedChannel.h:539 ]: [FBC 0x7f1a4c000d20] Calling dataFlushedCallback

[ D2 2023-08-04 18:48:09.5690 26/T9 Ser/HttpServer.h:1217 ]: [Client 2-3] Ending request

[ D3 2023-08-04 18:48:09.5690 26/T9 age/Cor/App/Socket.h:199 ]: Socket unix:/var/run/passenger-instreg/passenger.afaReFU/apps.s/ruby.2r1ia1AejvPHCqNjzs40Ker0r0uyrHKQ8MOcfrNtL: connection not checked back into connection pool. There are now 0 connections in total

[ D2 2023-08-04 18:48:09.5690 26/T9 age/Cor/App/Gro/SessionManagement.cpp:150 ]: Session closed for process (pid=728, group=/home/app (production))

[ D3 2023-08-04 18:48:09.5692 26/T9 Ser/FileBufferedChannel.h:1460 ]: [FBC 0x7f1a4c0015d8] Deinitialize

[ D3 2023-08-04 18:48:09.5692 26/T9 Ser/FileBufferedChannel.h:1416 ]: [FBC 0x7f1a4c000d20] Feeding 0 bytes

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/FileBufferedChannel.h:486 ]: [FBC 0x7f1a4c000d20] pushBuffer() completed: nbuffers = 1, bytesBuffered = 0

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/FileBufferedChannel.h:554 ]: [FBC 0x7f1a4c000d20] Reader: reading next

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/FileBufferedChannel.h:566 ]: [FBC 0x7f1a4c000d20] Reader: EOF encountered. Feeding EOF

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/FileBufferedChannel.h:582 ]: [FBC 0x7f1a4c000d20] Reader: EOF fed. Transitioning to RS_TERMINATED

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/FileBufferedChannel.h:539 ]: [FBC 0x7f1a4c000d20] Calling dataFlushedCallback

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/HttpServer.h:291 ]: [Client 2-3] Request refcount decreased; it is now 2

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/HttpServer.h:299 ]: [Client 2-3] Not keeping alive connection, disconnecting client

[ D2 2023-08-04 18:48:09.5693 26/T9 Ser/Server.h:1045 ]: [Client 2-3] Disconnecting; there are now 0 active clients

[ D3 2023-08-04 18:48:09.5693 26/T9 Ser/FileBufferedChannel.h:1460 ]: [FBC 0x7f1a4c000d20] Deinitialize

[ D2 2023-08-04 18:48:09.5693 26/T9 Ser/Server.h:1056 ]: [Client 2-3] Closing client file descriptor: 39

10.0.1.130 - - [04/Aug/2023:18:48:09 +0000] "GET /healthcheck HTTP/1.1" 502 54 "-" "ELB-HealthChecker/1.0"

[ D3 2023-08-04 18:48:09.5695 26/T9 Ser/Server.h:1067 ]: [Client 2-3] Refcount decreased; it is now 1

[ D3 2023-08-04 18:48:09.5695 26/T9 Ser/Channel.h:355 ]: [Client 2-3] Request refcount decreased; it is now 1

[ D3 2023-08-04 18:48:09.5695 26/T9 Ser/FdSourceChannel.h:55 ]: [Client 2-3] Request refcount decreased; it is now 0

[ D3 2023-08-04 18:48:09.5696 26/T9 Ser/HttpServer.h:213 ]: [Client 2-3] Request object reached a reference count of 0

[ D3 2023-08-04 18:48:09.5696 26/T9 Ser/HttpServer.h:220 ]: [Client 2-3] Request object added to freelist (0 -> 1)

[ D3 2023-08-04 18:48:09.5696 26/T9 Ser/HttpServer.h:232 ]: [Client 2-3] Refcount decreased; it is now 0

[ D3 2023-08-04 18:48:09.5696 26/T9 Ser/Server.h:490 ]: [Client 2-3] Client object reached a reference count of 0

[ D3 2023-08-04 18:48:09.5697 26/T9 Ser/Server.h:498 ]: [Client 2-3] Client object destroyed; not added to freelist because it's full (0)

[ D2 2023-08-04 18:48:09.6302 26/T17 age/Cor/App/Gro/ProcessListManagement.cpp:317 ]: Checking whether any of the 1 detached processes have exited...

[ D 2023-08-04 18:48:09.6302 26/T17 age/Cor/App/Gro/ProcessListManagement.cpp:327 ]: Detached process (pid=600, group=/home/app (production)) has 0 active sessions now. Triggering shutdown.

[ D2 2023-08-04 18:48:09.7306 26/T17 age/Cor/App/Gro/ProcessListManagement.cpp:317 ]: Checking whether any of the 1 detached processes have exited...

[ D 2023-08-04 18:48:09.7306 26/T17 age/Cor/App/Gro/ProcessListManagement.cpp:335 ]: Detached process (pid=600, group=/home/app (production)) has shut down. Cleaning up associated resources.

[ D2 2023-08-04 18:48:09.7306 26/T17 age/Cor/App/Process.h:620 ]: Cleaning up process (pid=600, group=/home/app (production))

We've read this optimizing phusion passenger with nginx article and tried setting passenger_max_pool_size and passenger_min_instances to the same value (relatively low value of 8). However the result was processes kept getting destroyed (perhaps because of the error) and passenger was constantly re-spawning processes and compromised its ability to serve requests.

We also changed the spawn method to direct instead of smart, since we are using memcached and read that there are issues with smart spawning sharing the memcached connection with multiple processes and trying to use it at the same time. Changing the method to direct seemed to help reduce the frequency of 502s, but did not eliminate them completely.

We're not sure what else could be causing this.

An early EOF is usually a configuration problem with your web server or reverse proxies, or possibly even an application timeout of some kind. There's not enough information here to debug this, and as it's more of a server configuration question it more likely belongs on ServerFault rather than SO. — Todd A. Jacobs, Aug 05 '23 at 18:36
With suitable editing and additional details, this is more appropriate for ServerFault. — Todd A. Jacobs, Aug 05 '23 at 18:37

Application sent EOF before finishing response headers resulting in 502

0 Answers0