search

phusion / passenger

A fast and robust web server and application server for Ruby, Python and Node.js
https://www.phusionpassenger.com/
MIT License
5k stars 547 forks source link

replies from app lost #2238

Open izenk opened 4 years ago

izenk commented 4 years ago

Issue report

Fill in as much as possible so that we can understand, find and fix the problem.

Are you sure this is a bug in Passenger? Please read our troubleshooting and debugging guides first: https://www.phusionpassenger.com/library/admin/troubleshooting/ https://www.phusionpassenger.com/library/admin/

Please try with the newest version of Passenger to avoid issues that have already been fixed

Question 1: What is the problem?

Your answer:

Question 2: Passenger version and integration mode:

Question 3: OS or Linux distro, platform (including version):

Question 4: Passenger installation method:

Your answer: [ ] Phusion APT repo

Question 5: Your app's programming language (including any version managers) and framework (including versions):

Your answer:

Question 6: Are you using a PaaS and/or containerization? If so which one?

We strive for quality and appreciate you taking the time to submit a report! Please note that if you want guaranteed response times and priority issue support we encourage you to join our enterprise customer base. They also provide us with the means to continue our high level of open source support!

CamJN commented 4 years ago

Can you set the log level to 7 and include more of the log?

https://www.phusionpassenger.com/docs/references/config_reference/nginx/#passenger_log_level

izenk commented 4 years ago

@CamJN, sure 

App 482 output: ======================================writeProcessing  <--------- 102 SENT HERE
App 482 output: ESC[0mPOST /api/subscription/create
App 482 output: CheckTaskStatus: Creating Virtual Datacenter vdc_3006611(f71013fe-e624-45a6-a471-a6c5df895641)
App 482 output: ======================================writeProcessing <--------- 102 SENT HERE
[ D3 2019-12-16 15:24:06.5636 31081/Tb Ser/FdSourceChannel.h:55 ]: [Client 2-11] Request refcount increased; it is now 2
[ D3 2019-12-16 15:24:06.5636 31081/Tb age/Cor/Con/ForwardResponse.cpp:64 ]: [Client 2-11] Event: onAppSourceData
[ D3 2019-12-16 15:24:06.5636 31081/Tb age/Cor/Con/ForwardResponse.cpp:75 ]: [Client 2-11] Processing 27 bytes of application data: "HTTP/1.1 102 Processing\r\n\r\n"
[ D2 2019-12-16 15:24:06.5636 31081/Tb age/Cor/Con/ForwardResponse.cpp:87 ]: [Client 2-11] Application response headers received
[ D2 2019-12-16 15:24:06.5636 31081/Tb age/Cor/Con/ForwardResponse.cpp:408 ]: [Client 2-11] Turbocache: preparing response caching
[ D 2019-12-16 15:24:06.5636 31081/Tb age/Cor/Con/ForwardResponse.cpp:423 ]: [Client 2-11] Processing turbocache invalidation based on response
[ D2 2019-12-16 15:24:06.5636 31081/Tb age/Cor/Con/ForwardResponse.cpp:426 ]: [Client 2-11] Turbocache entries:
 #0: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #1: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #2: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #3: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #4: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #5: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #6: valid=0, hash=0, expiryDate=0, keySize=0, key=""
 #7: valid=0, hash=0, expiryDate=0, keySize=0, key=""

[ D2 2019-12-16 15:24:06.5636 31081/Tb age/Cor/Con/ForwardResponse.cpp:830 ]: [Client 2-11] Sending response headers using writev()
[ D3 2019-12-16 15:24:06.5637 31081/Tb age/Cor/Con/ForwardResponse.cpp:899 ]: [Client 2-11] Sending response headers: "HTTP/1.1 102 Processing\r\nStatus: 102 Processing\r\nDate: Mon, 16 Dec 2019 15:24:06 GMT\r\nConnection: close\r\nX-Powered-By: Phusion Passenger 6.0.2\r\
n\r\n"
[ D2 2019-12-16 15:24:06.5637 31081/Tb age/Cor/Con/ForwardResponse.cpp:1077 ]: [Client 2-11] Keep-aliving application session connection
[ D3 2019-12-16 15:24:06.5637 31081/Tb age/Cor/App/Socket.h:201 ]: Socket unix:/tmp/passenger.f2Xgcg3/apps.s/node.1pfarz: connection not checked back into connection pool. There are now 0 connections in total
[ D2 2019-12-16 15:24:06.5637 31081/Tb age/Cor/App/Gro/SessionManagement.cpp:150 ]: Session closed for process (pid=31128, group=vcd)
[ D2 2019-12-16 15:24:06.5637 31081/Tb Ser/HttpServer.h:1217 ]: [Client 2-11] Ending request
[ D3 2019-12-16 15:24:06.5637 31081/Tb Ser/FileBufferedChannel.h:1460 ]: [FBC 0x7f4664001318] Deinitialize
[ D3 2019-12-16 15:24:06.5637 31081/Tb Ser/FileBufferedChannel.h:1416 ]: [FBC 0x7f46640081d0] Feeding 0 bytes
[ D3 2019-12-16 15:24:06.5637 31081/Tb Ser/FileBufferedChannel.h:486 ]: [FBC 0x7f46640081d0] pushBuffer() completed: nbuffers = 1, bytesBuffered = 0
[ D3 2019-12-16 15:24:06.5637 31081/Tb Ser/FileBufferedChannel.h:554 ]: [FBC 0x7f46640081d0] Reader: reading next
[ D3 2019-12-16 15:24:06.5637 31081/Tb Ser/FileBufferedChannel.h:566 ]: [FBC 0x7f46640081d0] Reader: EOF encountered. Feeding EOF
[ D3 2019-12-16 15:24:06.5637 31081/Tb Ser/FileBufferedChannel.h:582 ]: [FBC 0x7f46640081d0] Reader: EOF fed. Transitioning to RS_TERMINATED
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/FileBufferedChannel.h:539 ]: [FBC 0x7f46640081d0] Calling dataFlushedCallback
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/HttpServer.h:291 ]: [Client 2-11] Request refcount decreased; it is now 1
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/HttpServer.h:299 ]: [Client 2-11] Not keeping alive connection, disconnecting client
[ D2 2019-12-16 15:24:06.5638 31081/Tb Ser/Server.h:1046 ]: [Client 2-11] Disconnecting; there are now 0 active clients
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/FileBufferedChannel.h:1460 ]: [FBC 0x7f46640081d0] Deinitialize
[ D2 2019-12-16 15:24:06.5638 31081/Tb Ser/Server.h:1056 ]: [Client 2-11] Closing client file descriptor: 39
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/Server.h:1067 ]: [Client 2-11] Refcount decreased; it is now 1
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/FdSourceChannel.h:55 ]: [Client 2-11] Request refcount decreased; it is now 0
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/HttpServer.h:213 ]: [Client 2-11] Request object reached a reference count of 0
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/HttpServer.h:221 ]: [Client 2-11] Request object added to freelist (0 -> 1)
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/HttpServer.h:232 ]: [Client 2-11] Refcount decreased; it is now 0
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/Server.h:490 ]: [Client 2-11] Client object reached a reference count of 0
[ D3 2019-12-16 15:24:06.5638 31081/Tb Ser/Server.h:499 ]: [Client 2-11] Client object destroyed; not added to freelist because it's full (0)
App 482 output: ESC[0mPOST /api/subscription/

In general passenger says nothing during app attempt to send 102 to client. I only see string "======================================writeProcessing" in log and nothing more from passenger, just next "App stdout" strings. Sometimes, like in above example, passenger gives some additional string.

CamJN commented 4 years ago

I see that we send a Connection: close in the log, from reading the spec for http 102 it looks like the connection should be maintained, correct?

izenk commented 4 years ago

@CamJN yes, you are right. 102 spec came from webdav, but also is used by nodejs (docs)

If I start app without passenger, connection is maintained with 102 codes as some kind of keepalive messages.

CamJN commented 4 years ago

Ok i think this will require us to change how we handle 102 responses. I'm going to change to an enhancement request.