rubinius/rubinius — Issue #1367: passenger fails with 'Thread deadlock' 
Author: mustmodify
Created: 2011-10-26 00:15:11+00:00
State: open

I recently installed rbx-head using rvm. After trouble figuring out how to get passenger running on rbx2, I removed passenger and rebuilt from scratch.

Using a Nginx / Passenger / Rails (2 or 3) stack, when I go to a Rails action, rails renders a 200, but the resulting response is a 502 Bad Gateway. I've tracked this down to a locking problem in passenger.

if there are gem issues with the app, the passenger "failed to start" page shows, so passenger is working on some level. Also, of course, /images/rails.png works fine.

error log, versions, and nginx config:
https://gist.github.com/1314274

Tailing the Rails log, it looks like everything is fine:

Started GET "/" for 192.168.1.7 at Tue Oct 25 19:07:53 -0500 2011
Processing by PagesController#welcome as HTML
Rendered pages/welcome.html.haml (7.4ms)
Completed 200 OK in 44ms (Views: 41.4ms | ActiveRecord: 0.0ms)

However, nginx reports:

2011/10/25 19:07:54 [error] 3014#0: *114 upstream prematurely closed connection while reading response header from upstream, client: 192.168.1.7, server: dev.mustmodify.com, request: "GET / HTTP/1.1", upstream: "passenger:unix:/passenger_helper_server:", host: "dev.mustmodify.com"

and passenger says:

[ pid=6298 thr=82624 file=abstract_request_handler.rb:244 time=2011-10-25 19:07:42.676 ]: Entering request handler main loop
[ pid=6298 thr=82624 file=abstract_request_handler.rb:466 time=2011-10-25 19:07:42.678 ]: Accepting new request on main socket
Thread deadlock in ::lock()!
[ pid=2976 thr=139753104639744 file=ext/common/ApplicationPool/Pool.h:1162 time=2011-10-25 19:07:50.24 ]: Exception occurred while connecting to checked out process 6298: Cannot connect to Unix socket '/tmp/passenger.1.0.2972/generation-0/backends/ruby.WSF22kIBCegnDDjBN6Lk5dwEHKoqWywVA26Lyc7FPleGtWMRf4GU2DHy': Connection refused (111)
[ pid=2976 thr=139753104639744 file=ext/common/ApplicationPool/Pool.h:685 time=2011-10-25 19:07:50.24 ]: Detaching process 6298
[ pid=2976 thr=139753104639744 file=ext/common/ApplicationPool/../Process.h:138 time=2011-10-25 19:07:50.25 ]: Application process 6298 (0xfbb2a0): destroyed.
[ pid=2976 thr=139753104639744 file=ext/common/ApplicationPool/Pool.h:939 time=2011-10-25 19:07:50.25 ]: Spawning a process for /source/mustmodify/www because there are none for this app group
[ pid=2976 thr=139753104639744 file=ext/common/ApplicationPool/../SpawnManager.h:291 time=2011-10-25 19:07:50.25 ]: Spawning a new application process for /source/mustmodify/www...
[ pid=2976 thr=139753104639744 file=ext/common/ApplicationPool/../SpawnManager.h:413 time=2011-10-25 19:07:50.47 ]: Application process 6308 spawned
[ pid=2976 thr=139753104639744 file=ext/common/ApplicationPool/../Process.h:117 time=2011-10-25 19:07:50.47 ]: Application process 6308 (0xfbb950): created.
[ pid=6308 thr=82640 file=abstract_request_handler.rb:244 time=2011-10-25 19:07:52.256 ]: Entering request handler main loop
[ pid=6308 thr=82640 file=abstract_request_handler.rb:466 time=2011-10-25 19:07:52.258 ]: Accepting new request on main socket
Thread deadlock in ::lock()!