Debugging a Hanging Rails App -- Suspect blocking due to fil


I am debugging a Rails app which hangs every one to three days. The
process doesn’t crash; it just stops responding. I have been unable to
predictably reproduce this failure in a testing environment.

The hang occurs after a call to Authentication controller’s access
method (code below). This action is called many times each day but only
once in a while does the call cause a hang.

Right now, my hypothesis is that the hang is file system blocking caused
by a file lock. Tmpreaper runs every minute or two to remove old session
files. My limited knowledge of Linux file systems makes me think that if
it were, lsof would show it holding a lock.

The fact that lsof shows ruby holding two locks on the session file
makes me wonder if both Rail’s default session handling functionality
and the call to “, options)” are both trying to
keep the same file open, thus causing blocking.

Any clues on what might be causing this locking or how to resolve it?

Thank you,
Chicago 2006 Alumni

System Specs:
Ruby 1.8.5 built from stable source
Ubuntu 6.06
Rails 1.1.6 using Webrick behind an Apache 2 reverse proxy

Here’s relevant output from lsof from when the system hung this morning:
ruby 748 dailysuccess 6uW REG 104,1
0 167704
/tmp/sessions/dailysuccess/service/ruby_sess.e223f7c38046356c (deleted)
ruby 748 dailysuccess 7uW REG 104,1
0 167704
/tmp/sessions/dailysuccess/service/ruby_sess.e223f7c38046356c (deleted)

Using gdb to examine the process (thanks to Jamis B.‘s recent blog
postings) and execute a backtrace reveals:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:292:in flock'" 0x89c1798: "/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:292:intransaction’"
update'" 0x87d2438: "/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session/pstore.rb:88:inclose’”
callback'" 0x87d24e0: "/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:368:incall’”
“/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:368:in commit_new'" 0x87d2578: "/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:334:intransaction’”
initialize'" 0x87d2620: "/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session.rb:273:innew’”
initialize'" 0x87d26c0: "/var/iblp/dailysuccess/service/current-version/script/../config/../app/controllers/authentication_controller.rb:5:innew’”

And here are a few lines from the process backtrace:
#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb7f0508d in select () from /lib/tls/i686/cmov/
#2 0x0806842e in rb_thread_schedule () at …/ruby-1.8.5/eval.c:10638
#3 0x080697e3 in rb_thread_polling () at …/ruby-1.8.5/eval.c:11349
#4 0x0806f1ab in rb_thread_flock (fd=7, op=6, fptr=0x8251c48) at
#5 0x0806f299 in rb_file_flock (obj=3080224540, operation=5) at
#6 0x0805f1a4 in call_cfunc (func=0x806f1e3 <rb_file_flock>,
recv=3080224540, len=1, argc=1, argv=0xbfbc2290) at
#7 0x0805e6c8 in rb_call0 (klass=3085134580, recv=3080224540, id=8281,
oid=8281, argc=1, argv=0xbfbc2290, body=0xb7e35a28, flags=0)
at …/ruby-1.8.5/eval.c:5810
#8 0x0805fc86 in rb_call (klass=3085134580, recv=3080224540, mid=8281,
argc=1, argv=0xbfbc2290, scope=0) at …/ruby-1.8.5/eval.c:6048
#9 0x08058b53 in rb_eval (self=3079764800, n=0xb7bad184) at

class AuthenticationController < ApplicationController

Called by an external template system to determine if Web visitor is

allowed access.

Template system retrieves cookie from client and passes session ID

into this action

which loads the session into memory in the Rails application.

def access
options = default_session_options.stringify_keys.update(‘session_id’
=> @params[:id])
session =, options)
render(:text => logged_in?(session) ? ‘true’ : ‘false’)

def default_session_options

def logged_in?(session)