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.

Sign up for GitHub

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

Jump to bottom

Crash on download request for large files #1706

Closed
jklimke opened this issue Dec 16, 2015 · 8 comments
Closed

Crash on download request for large files #1706

jklimke opened this issue Dec 16, 2015 · 8 comments
Labels
CannotReproduce NeedsFeedback

Comments

@jklimke
Copy link

jklimke commented Dec 16, 2015

I am experiencing a reproduceable crash with passenger in combination with nginx when requesting a download of a large file (~600 MB) via rails and dragonfly. Smaller file download are working well.

The request results in the following log entries:

[ 2015-12-16 16:39:53.7678 896/7fe741ffb700 age/Cor/Con/InternalUtils.cpp:105 ]: [Client 5-3] Sending 502 response: application did not send a complete response
App 1211 stderr: [ 2015-12-16 16:39:53.7680 1304/0x0000000257f290(Worker 1) utils.rb:87 ]: *** Exception SystemStackError (stack level too deep) (process 1304, thread 0x0000000257f290(Worker 1)):
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/ruby_core_io_enhancements.rb:49:in `writev2'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/ruby_core_io_enhancements.rb:49:in `writev2'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/utils/unseekable_socket.rb:133:in `writev2'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:283:in `process_body'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:146:in `process_request'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:152:in `accept_and_process_next_request'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
App 1211 stderr:        from /usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'
[ 2015-12-16 16:39:58.0492 896/7fe7571b0700 age/Cor/App/Poo/AnalyticsCollection.cpp:105 ]: Process (pid=1304, group=/usr/share/nginx/videocreator/current/public) no longer exists! Detaching it from the pool.
[ 2015-12-16 16:39:58.0493 896/7fe7571b0700 age/Cor/CoreMain.cpp:794 ]: Disconnecting long-running connections for process 1304, application /usr/share/nginx/videocreator/current/public
App 1332 stdout:

Version: Phusion Passenger 5.0.22
passenger_ruby in nginx.conf ruby 2.2.1p85
Rails version 4.2.4
System: Ubuntu 14.04
Passenger was installed from apt-sources
@OnixGH
Copy link
Contributor

OnixGH commented Dec 16, 2015

Thanks for reporting!

What OS are you on? Would you be able to send us a complete log with log level set to 7?

@jklimke
Copy link
Author

jklimke commented Dec 16, 2015

It is running on ubuntu 14.04

Here is the log level 7 output for the request. I replaced the URL against example.org.

[ 2015-12-16 17:38:01.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:160 ]: Analytics collection time...
[ 2015-12-16 17:38:01.0002 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:187 ]: Collecting process metrics
[ 2015-12-16 17:38:01.0002 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 99
[ 2015-12-16 17:38:01.0051 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 100
[ 2015-12-16 17:38:01.0061 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 100
[ 2015-12-16 17:38:01.0259 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 99
[ 2015-12-16 17:38:01.0329 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:01.0395 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:01.0395 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:195 ]: Collecting system metrics
[ 2015-12-16 17:38:01.0396 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:01.0397 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:01.0398 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:01.0399 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:72 ]: Analytics collection done; next analytics collection in 4.960 sec
[ 2015-12-16 17:38:03.1813 12394/7f74c9c3f700 age/Ust/Controller.h:721 ]: Flushing sinks that need flushing
[ 2015-12-16 17:38:03.1814 12394/7f74c9c3f700 age/Ust/Controller.h:735 ]: Done flushing sinks that need flushing
[ 2015-12-16 17:38:03.8774 12388/7fe888ff9700 Ser/AcceptLoadBalancer.h:194 ]: File descriptor opened: 99
[ 2015-12-16 17:38:03.8774 12388/7fe888ff9700 Ser/AcceptLoadBalancer.h:136 ]: Accepted client file descriptor: 99
[ 2015-12-16 17:38:03.8774 12388/7fe888ff9700 Ser/AcceptLoadBalancer.h:194 ]: File descriptor opened: -1
[ 2015-12-16 17:38:03.8774 12388/7fe888ff9700 Ser/AcceptLoadBalancer.h:164 ]: Feeding client to server thread 3: file descriptor 99
[ 2015-12-16 17:38:03.8775 12388/7fe8c27fc700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:03.8775 12388/7fe8c27fc700 Ser/Server.h:353 ]: [ServerThr.4] Checking out client object from freelist (128 -> 127)
[ 2015-12-16 17:38:03.8776 12388/7fe8c27fc700 Ser/Server.h:576 ]: [Client 4-1] Client associated with file descriptor: 99
[ 2015-12-16 17:38:03.8776 12388/7fe8c27fc700 Ser/Server.h:733 ]: File descriptor purpose: 99: Server ServerThr.4, client 4-1
[ 2015-12-16 17:38:03.8776 12388/7fe8c27fc700 Ser/Server.h:737 ]: [ServerThr.4] 1 new client(s) accepted; there are now 1 active client(s)
[ 2015-12-16 17:38:03.8776 12388/7fe8c27fc700 Ser/HttpServer.h:669 ]: [Client 4-1] Event: onClientAccepted
[ 2015-12-16 17:38:03.8776 12388/7fe8c27fc700 Ser/HttpServer.h:236 ]: [Client 4-1] Refcount increased; it is now 3
[ 2015-12-16 17:38:03.8776 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:1450 ]: [FBC 0x1381190] Deinitialize
[ 2015-12-16 17:38:03.8776 12388/7fe8c27fc700 Ser/HttpServer.h:130 ]: [ServerThr.4] Creating new request object
[ 2015-12-16 17:38:03.8777 12388/7fe8c27fc700 Ser/Server.h:453 ]: [Client 4-1] Processing 464 bytes of client data
[ 2015-12-16 17:38:03.8777 12388/7fe8c27fc700 Ser/HttpServer.h:677 ]: [Client 4-1] Event: onClientDataReceived
[ 2015-12-16 17:38:03.8777 12388/7fe8c27fc700 Ser/HttpServer.h:680 ]: [Client 4-1] Request refcount increased; it is now 2
[ 2015-12-16 17:38:03.8777 12388/7fe8c27fc700 Ser/HttpServer.h:257 ]: [Client 4-1] Parsing 464 bytes of HTTP header: "GET /media/W1siZiIsIjIwMTUvMTIvMTYvNjFpODN3ejd3bl9UZXN0dmlkZW9fMV9fM18ubXA0Il1d/Testvideo_1__3_.mp4?sha=043c7c3204fdf729 HTTP/1.1\r\nConnection: close\r\nHost: example.org\r\nConnection: keep-alive\r\nUser-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36\r\nAccept-Encoding: gzip, deflate, sdch\r\nAccept-Language: de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4\r\nCookie: _videomaker_session=cHRZRythem5"
[ 2015-12-16 17:38:03.8777 12388/7fe8c27fc700 Ser/HttpServer.h:680 ]: [Client 4-1] Request refcount decreased; it is now 1
[ 2015-12-16 17:38:03.8777 12388/7fe8c27fc700 Ser/Server.h:480 ]: [Client 4-1] 464 bytes of client data consumed in this callback
[ 2015-12-16 17:38:03.8778 12388/7fe8c27fc700 Ser/Server.h:529 ]: [Client 4-1] Refcount decreased; it is now 2
[ 2015-12-16 17:38:03.8778 12388/7fe8c27fc700 Ser/FdSourceChannel.h:55 ]: [Client 4-1] Refcount increased; it is now 3
[ 2015-12-16 17:38:03.8778 12388/7fe8c27fc700 Ser/Server.h:453 ]: [Client 4-1] Processing 464 bytes of client data
[ 2015-12-16 17:38:03.8778 12388/7fe8c27fc700 Ser/HttpServer.h:677 ]: [Client 4-1] Event: onClientDataReceived
[ 2015-12-16 17:38:03.8778 12388/7fe8c27fc700 Ser/HttpServer.h:680 ]: [Client 4-1] Request refcount increased; it is now 2
[ 2015-12-16 17:38:03.8778 12388/7fe8c27fc700 Ser/HttpServer.h:257 ]: [Client 4-1] Parsing 464 bytes of HTTP header: "OTnZjNzgyY0ZLMWd4ejNQRXRDZ01ORXdEbUtWM2hpY1ZYWlpMZ0hUZFBGVnF3R0RwemhmdUdjKzZHeFdrRENMdk1TVkptTlBFZWpwL2VxRFRvK0ZRc2VteVpXaGZ0TUZGNmx0d1JxVXZtc0dhb1lzcHlCUCt0Q2ZVTmhteDUvbmVPYkRjMDRPZS9Vd3FBemZuNkk5b3NSb1NDRjRITWIvV2c3cWRmUXRucEhDa05lVE40Y05oN24rS0hsS2RzL1FjM0JWZWxxWkJJTnZDTGl5SDIxVnJTYlBncHIxaFJnRFlxTT0tLVNpb1NZWlg5RFQvQzdVTGRCVFRDOUE9PQ%3D%3D--c30ce41fa6d6eab326cb1dff871705216d7760a5; _passenger_route=2002048515\r\n!~: ti114sCGR6A0nPSkCHXC67ri\r\n!~DOCUMENT_ROOT:"
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/HttpServer.h:680 ]: [Client 4-1] Request refcount decreased; it is now 1
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/Server.h:480 ]: [Client 4-1] 464 bytes of client data consumed in this callback
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/FdSourceChannel.h:55 ]: [Client 4-1] Refcount decreased; it is now 2
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/FdSourceChannel.h:55 ]: [Client 4-1] Refcount increased; it is now 3
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/Server.h:453 ]: [Client 4-1] Processing 311 bytes of client data
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/HttpServer.h:677 ]: [Client 4-1] Event: onClientDataReceived
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/HttpServer.h:680 ]: [Client 4-1] Request refcount increased; it is now 2
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/HttpServer.h:257 ]: [Client 4-1] Parsing 311 bytes of HTTP header: " /usr/share/nginx/videocreator/current/public\r\n!~REMOTE_ADDR: 141.89.226.146\r\n!~REMOTE_PORT: 58737\r\n!~PASSENGER_APP_GROUP_NAME: /usr/share/nginx/videocreator/current/public\r\n!~PASSENGER_APP_TYPE: rack\r\n!~PASSENGER_RUBY: /usr/local/rvm/wrappers/videoservice/ruby\r\n!~PASSENGER_STICKY_SESSIONS: t\r\n!~FLAGS: DCS\r\n\r\n"
[ 2015-12-16 17:38:03.8779 12388/7fe8c27fc700 Ser/HttpServer.h:268 ]: [Client 4-1] New request received: #1
[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:492 ]: [Client 4-1] Initiating request
[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:87 ]: [Client 4-1] Dechunk flag detected
[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:93 ]: [Client 4-1] HTTPS flag detected
[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:96 ]: [Client 4-1] Stripping 100 Continue header
[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:109 ]: [Client 4-1] Turbocaching: trying to reply from cache (key "Sexample.org\n/media/W1siZiIsIjIwMTUvMTIvMTYvNjFpODN3ejd3bl9UZXN0dmlkZW9fMV9fM18ubXA0Il1d/Testvideo_1__3_.mp4?sha=043c7c3204fdf729")
[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:110 ]: [Client 4-1] 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=""

[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:126 ]: [Client 4-1] Turbocaching: cache miss: NOT_FOUND (key "Sexample.org\n/media/W1siZiIsIjIwMTUvMTIvMTYvNjFpODN3ejd3bl9UZXN0dmlkZW9fMV9fM18ubXA0Il1d/Testvideo_1__3_.mp4?sha=043c7c3204fdf729")
[ 2015-12-16 17:38:03.8780 12388/7fe8c27fc700 age/Cor/Con/InitRequest.cpp:300 ]: [Client 4-1] Creating new pool options: app group name=/usr/share/nginx/videocreator/current/public
[ 2015-12-16 17:38:03.8781 12388/7fe8c27fc700 age/Cor/Con/CheckoutSession.cpp:55 ]: [Client 4-1] Checking out session: appRoot=/usr/share/nginx/videocreator/current
[ 2015-12-16 17:38:03.8781 12388/7fe8c27fc700 age/Cor/Con/CheckoutSession.cpp:69 ]: [Client 4-1] Request refcount increased; it is now 3
[ 2015-12-16 17:38:03.8782 12388/7fe8c27fc700 age/Cor/App/Poo/Miscellaneous.cpp:49 ]: asyncGet(appGroupName=/usr/share/nginx/videocreator/current/public)
[ 2015-12-16 17:38:03.8782 12388/7fe8c27fc700 age/Cor/App/Poo/Miscellaneous.cpp:55 ]: Found existing Group
[ 2015-12-16 17:38:03.8782 12388/7fe8c27fc700 age/Cor/App/Gro/SessionManagement.cpp:330 ]: Session checked out from process (pid=12621, group=/usr/share/nginx/videocreator/current/public)
[ 2015-12-16 17:38:03.8782 12388/7fe8c27fc700 age/Cor/App/Poo/Miscellaneous.cpp:60 ]: asyncGet() finished
[ 2015-12-16 17:38:03.8782 12388/7fe8c27fc700 age/Cor/Con/CheckoutSession.cpp:133 ]: [Client 4-1] Session checked out: pid=12621, gupid=170d385-QuLaB0wPPM
[ 2015-12-16 17:38:03.8783 12388/7fe8c27fc700 age/Cor/App/Socket.h:168 ]: Socket unix:/tmp/passenger.o7K7fhE/apps.s/ruby.72tS6LUXuTf3XkkaiuCkCDP277TgF7delqxZ1qftCRPXReMGeTNiCgaZbLJsW66: checking out connection from connection pool (1 -> 0 items). Current total number of connections: 1
[ 2015-12-16 17:38:03.8783 12388/7fe8c27fc700 age/Cor/Con/CheckoutSession.cpp:201 ]: [Client 4-1] Session initiated: fd=106
[ 2015-12-16 17:38:03.8783 12388/7fe8c27fc700 age/Cor/Con/SendRequest.cpp:90 ]: [Client 4-1] Sending headers to application with session protocol
[ 2015-12-16 17:38:03.8783 12388/7fe8c27fc700 age/Cor/Con/SendRequest.cpp:169 ]: [Client 4-1] Header data: "\000\000\004\336REQUEST_URI\000/media/W1siZiIsIjIwMTUvMTIvMTYvNjFpODN3ejd3bl9UZXN0dmlkZW9fMV9fM18ubXA0Il1d/Testvideo_1__3_.mp4?sha=043c7c3204fdf729\000PATH_INFO\000/media/W1siZiIsIjIwMTUvMTIvMTYvNjFpODN3ejd3bl9UZXN0dmlkZW9fMV9fM18ubXA0Il1d/Testvideo_1__3_.mp4\000SCRIPT_NAME\000\000QUERY_STRING\000sha=043c7c3204fdf729\000REQUEST_METHOD\000GET\000SERVER_NAME\000example.org\000SERVER_PORT\000443\000SERVER_SOFTWARE\000nginx/1.8.0 Phusion_Passenger/5.0.22\000SERVER_PROTOCOL\000HTTP/1.1\000REMOTE_ADDR\000141.89.226.146\000REMOTE_PORT\00058737\000PASSENGER_CONNECT_PASSWORD\000goDxlXPO8i1ceSVj\000HTTPS\000on\000HTTP_USER_AGENT\000Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.80 Safari/537.36\000HTTP_ACCEPT_LANGUAGE\000de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4\000HTTP_ACCEPT_ENCODING\000gzip, deflate, sdch\000HTTP_COOKIE\000_videomaker_session=cHRZRythem5OTnZjNzgyY0ZLMWd4ejNQRXRDZ01ORXdEbUtWM2hpY1ZYWlpMZ0hUZFBGVnF3R0RwemhmdUdjKzZHeFdrRENMdk1TVkptTlBFZWpwL2VxRFRvK0ZRc2VteVpXaGZ0TUZGNmx0d1JxVXZtc0dhb1lzcHlCUCt0Q2ZVTmhteDUvbmVPYkRjMDRPZS9Vd3FBemZuNkk5b3NSb1NDRjRITWIvV2c3cWRmUXRucEhDa05lVE40Y05oN24rS0hsS2RzL1FjM0JWZWxxWkJJTnZDTGl5SDIxVnJTYlBncHIxaFJnRFlxTT0tLVNpb1NZWlg5RFQvQzdVTGRCVFRDOUE9PQ%3D%3D--c30ce41fa6d6eab326cb1dff871705216d7760a5; _passenger_route=2002048515\000HTTP_HOST\000example.org\000"
[ 2015-12-16 17:38:03.8784 12388/7fe8c27fc700 age/Cor/Con/SendRequest.cpp:945 ]: [Client 4-1] No body to send to application
[ 2015-12-16 17:38:03.8784 12388/7fe8c27fc700 age/Cor/Con/CheckoutSession.cpp:94 ]: [Client 4-1] Request refcount decreased; it is now 2
[ 2015-12-16 17:38:03.8784 12388/7fe8c27fc700 Ser/HttpServer.h:680 ]: [Client 4-1] Request refcount decreased; it is now 1
[ 2015-12-16 17:38:03.8784 12388/7fe8c27fc700 Ser/Server.h:480 ]: [Client 4-1] 311 bytes of client data consumed in this callback
[ 2015-12-16 17:38:03.8784 12388/7fe8c27fc700 Ser/FdSourceChannel.h:55 ]: [Client 4-1] Refcount decreased; it is now 2
App 12533 stderr: [ 2015-12-16 17:38:03.8786 12621/0x00000001502980(Worker 1) request_handler/thread_handler.rb:142 ]: Accepted new request on socket main socket
[ 2015-12-16 17:38:06.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:160 ]: Analytics collection time...
[ 2015-12-16 17:38:06.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:187 ]: Collecting process metrics
[ 2015-12-16 17:38:06.0002 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 100
[ 2015-12-16 17:38:06.0005 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 105
[ 2015-12-16 17:38:06.0012 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 105
[ 2015-12-16 17:38:06.0142 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 100
[ 2015-12-16 17:38:06.0205 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 100
[ 2015-12-16 17:38:06.0363 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 100
[ 2015-12-16 17:38:06.0363 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:195 ]: Collecting system metrics
[ 2015-12-16 17:38:06.0364 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 100
[ 2015-12-16 17:38:06.0366 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 100
[ 2015-12-16 17:38:06.0367 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 100
[ 2015-12-16 17:38:06.0368 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:72 ]: Analytics collection done; next analytics collection in 4.963 sec
App 12533 stderr: [ 2015-12-16 17:38:06.4412 12621/0x00000001502980(Worker 1) request_handler/thread_handler.rb:172 ]: Request done.
[ 2015-12-16 17:38:06.4413 12388/7fe8c2ffd700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:06.4414 12388/7fe8c27fc700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:06.4414 12388/7fe8c27fc700 Ser/FdSourceChannel.h:55 ]: [Client 4-1] Request refcount increased; it is now 2
[ 2015-12-16 17:38:06.4414 12388/7fe8c27fc700 age/Cor/Con/ForwardResponse.cpp:64 ]: [Client 4-1] Event: onAppSourceData
[ 2015-12-16 17:38:06.4414 12388/7fe8c27fc700 age/Cor/Con/ForwardResponse.cpp:131 ]: [Client 4-1] Application sent EOF before finishing response headers
[ 2015-12-16 17:38:06.4414 12388/7fe8c27fc700 age/Cor/Con/InternalUtils.cpp:105 ]: [Client 4-1] Sending 502 response: application did not send a complete response
[ 2015-12-16 17:38:06.4415 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:1406 ]: [FBC 0x1381190] Feeding 223 bytes
App 12533 stderr: [ 2015-12-16 17:38:06.4415 12621/0x00000001502980(Worker 1) utils.rb:87 ]: *** Exception SystemStackError (stack level too deep) (process 12621, thread 0x00000001502980(Worker 1)):
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/ruby_core_io_enhancements.rb:49:in `writev2'
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/ruby_core_io_enhancements.rb:49:in `writev2'
[ 2015-12-16 17:38:06.4415 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:485 ]: [FBC 0x1381190] pushBuffer() completed: nbuffers = 1, bytesBuffered = 223
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/utils/unseekable_socket.rb:133:in `writev2'
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:283:in `process_body'
[ 2015-12-16 17:38:06.4415 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:553 ]: [FBC 0x1381190] Reader: reading next
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:146:in `process_request'
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:152:in `accept_and_process_next_request'
[ 2015-12-16 17:38:06.4415 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:585 ]: [FBC 0x1381190] Reader: found buffer, 223 bytes
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
[ 2015-12-16 17:38:06.4415 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:492 ]: [FBC 0x1381190] popBuffer() completed: nbuffers = 0, bytesBuffered = 0
App 12533 stderr:   from /usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:593 ]: [FBC 0x1381190] Reader: feeding buffer, 223 bytes
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:553 ]: [FBC 0x1381190] Reader: reading next
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:560 ]: [FBC 0x1381190] Reader: no more buffers. Transitioning to RS_INACTIVE
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:538 ]: [FBC 0x1381190] Calling dataFlushedCallback
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:1406 ]: [FBC 0x1381190] Feeding 54 bytes
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:485 ]: [FBC 0x1381190] pushBuffer() completed: nbuffers = 1, bytesBuffered = 54
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:553 ]: [FBC 0x1381190] Reader: reading next
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:585 ]: [FBC 0x1381190] Reader: found buffer, 54 bytes
[ 2015-12-16 17:38:06.4416 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:492 ]: [FBC 0x1381190] popBuffer() completed: nbuffers = 0, bytesBuffered = 0
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:593 ]: [FBC 0x1381190] Reader: feeding buffer, 54 bytes
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:553 ]: [FBC 0x1381190] Reader: reading next
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:560 ]: [FBC 0x1381190] Reader: no more buffers. Transitioning to RS_INACTIVE
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:538 ]: [FBC 0x1381190] Calling dataFlushedCallback
App 12533 stderr: [ 2015-12-16 17:38:06.4416 12621/0x000000012cf320(Main thread) request_handler.rb:219 ]: Request handler main loop interrupted by SystemExit exception
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 Ser/HttpServer.h:1061 ]: [Client 4-1] Ending request
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 age/Cor/App/Socket.h:191 ]: Socket unix:/tmp/passenger.o7K7fhE/apps.s/ruby.72tS6LUXuTf3XkkaiuCkCDP277TgF7delqxZ1qftCRPXReMGeTNiCgaZbLJsW66: connection not checked back into connection pool. There are now 0 connections in total
App 12533 stderr: [ 2015-12-16 17:38:06.4417 12621/0x000000012cf320(Main thread) request_handler.rb:222 ]: Exiting request handler main loop
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 age/Cor/App/Socket.h:69 ]: File descriptor closed: 106
[ 2015-12-16 17:38:06.4417 12388/7fe8c27fc700 age/Cor/App/Gro/SessionManagement.cpp:150 ]: Session closed for process (pid=12621, group=/usr/share/nginx/videocreator/current/public)
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:1450 ]: [FBC 0x7fe8a8000e70] Deinitialize
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:1406 ]: [FBC 0x1381190] Feeding 0 bytes
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:485 ]: [FBC 0x1381190] pushBuffer() completed: nbuffers = 1, bytesBuffered = 0
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:553 ]: [FBC 0x1381190] Reader: reading next
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:565 ]: [FBC 0x1381190] Reader: EOF encountered. Feeding EOF
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:581 ]: [FBC 0x1381190] Reader: EOF fed. Transitioning to RS_TERMINATED
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:538 ]: [FBC 0x1381190] Calling dataFlushedCallback
[ 2015-12-16 17:38:06.4418 12388/7fe8c27fc700 Ser/HttpServer.h:220 ]: [Client 4-1] Request refcount decreased; it is now 1
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/HttpServer.h:225 ]: [Client 4-1] Not keeping alive connection, disconnecting client
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/Server.h:903 ]: [Client 4-1] Disconnecting; there are now 0 active clients
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/FileBufferedChannel.h:1450 ]: [FBC 0x1381190] Deinitialize
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/Server.h:913 ]: [Client 4-1] Closing client file descriptor: 99
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/Server.h:916 ]: File descriptor closed: 99
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/Server.h:924 ]: [Client 4-1] Refcount decreased; it is now 1
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/FdSourceChannel.h:55 ]: [Client 4-1] Request refcount decreased; it is now 0
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/HttpServer.h:147 ]: [Client 4-1] Request object reached a reference count of 0
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/HttpServer.h:155 ]: [Client 4-1] Request object added to freelist (0 -> 1)
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/HttpServer.h:162 ]: [Client 4-1] Refcount decreased; it is now 0
[ 2015-12-16 17:38:06.4419 12388/7fe8c27fc700 Ser/Server.h:379 ]: [Client 4-1] Client object reached a reference count of 0
[ 2015-12-16 17:38:06.4420 12388/7fe8c27fc700 Ser/Server.h:385 ]: [Client 4-1] Client object added to freelist (127 -> 128)
[ 2015-12-16 17:38:08.1814 12394/7f74c9c3f700 age/Ust/Controller.h:721 ]: Flushing sinks that need flushing
[ 2015-12-16 17:38:08.1815 12394/7f74c9c3f700 age/Ust/Controller.h:735 ]: Done flushing sinks that need flushing
[ 2015-12-16 17:38:11.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:160 ]: Analytics collection time...
[ 2015-12-16 17:38:11.0002 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:187 ]: Collecting process metrics
[ 2015-12-16 17:38:11.0023 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 99
[ 2015-12-16 17:38:11.0023 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 100
[ 2015-12-16 17:38:11.0033 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 100
[ 2015-12-16 17:38:11.0221 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 99
[ 2015-12-16 17:38:11.0293 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:11.0294 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:195 ]: Collecting system metrics
[ 2015-12-16 17:38:11.0294 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:11.0296 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:11.0297 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:11.0298 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:105 ]: Process (pid=12621, group=/usr/share/nginx/videocreator/current/public) no longer exists! Detaching it from the pool.
[ 2015-12-16 17:38:11.0299 12388/7fe8d704d700 age/Cor/App/Gro/ProcessListManagement.cpp:476 ]: Detaching process (pid=12621, group=/usr/share/nginx/videocreator/current/public)
[ 2015-12-16 17:38:11.0299 12388/7fe8d704d700 age/Cor/CoreMain.cpp:794 ]: Disconnecting long-running connections for process 12621, application /usr/share/nginx/videocreator/current/public
[ 2015-12-16 17:38:11.0300 12388/7fe8c3fff700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe8c27fc700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe8c37fe700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe8c2ffd700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe88b7fe700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe8c0ff9700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe8c1ffb700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe8c17fa700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0300 12388/7fe88bfff700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0301 12388/7fe88a7fc700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0301 12388/7fe8d704d700 age/Cor/App/Gro/ProcessListManagement.cpp:274 ]: Starting detached processes checker
[ 2015-12-16 17:38:11.0301 12388/7fe88affd700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0301 12388/7fe889ffb700 age/Cor/Con/TurboCaching.h:245 ]: Clearing turbocache
[ 2015-12-16 17:38:11.0302 12388/7fe8885ab700 age/Cor/App/Gro/ProcessListManagement.cpp:311 ]: Checking whether any of the 1 detached processes have exited...
[ 2015-12-16 17:38:11.0302 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:72 ]: Analytics collection done; next analytics collection in 4.970 sec
[ 2015-12-16 17:38:11.0303 12388/7fe8885ab700 age/Cor/App/Gro/ProcessListManagement.cpp:321 ]: Detached process (pid=12621, group=/usr/share/nginx/videocreator/current/public) has 0 active sessions now. Triggering shutdown.
[ 2015-12-16 17:38:11.1304 12388/7fe8885ab700 age/Cor/App/Gro/ProcessListManagement.cpp:311 ]: Checking whether any of the 1 detached processes have exited...
[ 2015-12-16 17:38:11.1304 12388/7fe8885ab700 age/Cor/App/Gro/ProcessListManagement.cpp:328 ]: Detached process (pid=12621, group=/usr/share/nginx/videocreator/current/public) has shut down. Cleaning up associated resources.
[ 2015-12-16 17:38:11.1305 12388/7fe8885ab700 age/Cor/App/Process.h:573 ]: Cleaning up process (pid=12621, group=/usr/share/nginx/videocreator/current/public)
[ 2015-12-16 17:38:11.1305 12388/7fe8885ab700 FileDescriptor.h:84 ]: File descriptor closed: 104
[ 2015-12-16 17:38:11.1306 12388/7fe8885ab700 age/Cor/App/Gro/ProcessListManagement.cpp:354 ]: Stopping detached processes checker
[ 2015-12-16 17:38:13.1816 12394/7f74c9c3f700 age/Ust/Controller.h:721 ]: Flushing sinks that need flushing
[ 2015-12-16 17:38:13.1816 12394/7f74c9c3f700 age/Ust/Controller.h:735 ]: Done flushing sinks that need flushing
[ 2015-12-16 17:38:16.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:160 ]: Analytics collection time...
[ 2015-12-16 17:38:16.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:187 ]: Collecting process metrics
[ 2015-12-16 17:38:16.0002 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 99
[ 2015-12-16 17:38:16.0050 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 100
[ 2015-12-16 17:38:16.0060 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 100
[ 2015-12-16 17:38:16.0251 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 99
[ 2015-12-16 17:38:16.0319 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:16.0320 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:195 ]: Collecting system metrics
[ 2015-12-16 17:38:16.0321 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:16.0322 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:16.0323 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:16.0324 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:72 ]: Analytics collection done; next analytics collection in 4.968 sec
[ 2015-12-16 17:38:18.1817 12394/7f74c9c3f700 age/Ust/Controller.h:721 ]: Flushing sinks that need flushing
[ 2015-12-16 17:38:18.1817 12394/7f74c9c3f700 age/Ust/Controller.h:735 ]: Done flushing sinks that need flushing
[ 2015-12-16 17:38:21.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:160 ]: Analytics collection time...
[ 2015-12-16 17:38:21.0001 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:187 ]: Collecting process metrics
[ 2015-12-16 17:38:21.0002 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 99
[ 2015-12-16 17:38:21.0051 12388/7fe8d704d700 Utils.cpp:1040 ]: File descriptor opened: 100
[ 2015-12-16 17:38:21.0061 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 100
[ 2015-12-16 17:38:21.0256 12388/7fe8d704d700 FileDescriptor.h:94 ]: File descriptor closed: 99
[ 2015-12-16 17:38:21.0326 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:21.0327 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:195 ]: Collecting system metrics
[ 2015-12-16 17:38:21.0327 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:21.0329 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:21.0330 12388/7fe8d704d700 Uti/ScopeGuard.h:114 ]: File descriptor closed: 99
[ 2015-12-16 17:38:21.0331 12388/7fe8d704d700 age/Cor/App/Poo/AnalyticsCollection.cpp:72 ]: Analytics collection done; next analytics collection in 4.967 sec
[ 2015-12-16 17:38:23.1818 12394/7f74c9c3f700 age/Ust/Controller.h:721 ]: Flushing sinks that need flushing
[ 2015-12-16 17:38:23.1818 12394/7f74c9c3f700 age/Ust/Controller.h:735 ]: Done flushing sinks that need flushing

@jklimke
Copy link
Author

jklimke commented Jan 5, 2016

Are there any hints how to prevent this error ? As far as we tested it it works when using apache together with passenger.

@OnixGH
Copy link
Contributor

OnixGH commented Jan 11, 2016

We'll need some time to look into this. I wouldn't have expected a stack overflow error to come out of something size related though, are you using symlinks in your setup? We saw an overflow issue in #1596 with that.

@jklimke
Copy link
Author

jklimke commented Jan 11, 2016

Yes we are making use of symlinks for deployment. It is a usual capistrano deployed rails application so we there are quite many symlinks in the application path and especially in the path to the files to be downloaded.

@jklimke
Copy link
Author

jklimke commented Jul 12, 2016

Any progress here ?

@OnixGH
Copy link
Contributor

OnixGH commented Jul 12, 2016

Unfortunately we've not been able to reproduce this so far. If you had a test app somewhere we could run, it would be a great help for diagnosing.

@FooBarWidget
Copy link
Member

Hi, unfortunately we've not been able to help so far due to inability to reproduce. Since there hasn't been any updates on this issue, I'm closing this. If you are still experiencing problems then please feel free to request a reopen.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
CannotReproduce NeedsFeedback
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@FooBarWidget @jklimke @OnixGH