Lots of file uploads leads to deadlock

[cannikin]

Not sure if this is actually a rack issue, but rack is the one complaining about this deadlock so I thought I'd start there. :)

I've got a Rails 3.1rc1 app that allows uploading of multiple files at once via a jQuery plugin called File Upload: http://aquantum-demo.appspot.com/file-upload This allows the user to upload a bunch of images which I then resize by farming out to ImageMagick's convert command and then upload to S3. My site is served by two Unicorn workers.

Last night I was uploading a batch of about 30 images at once. It looks like Chrome will do 6 simultaneously and it got through about half the batch before this started showing up in my unicorn.stderr.log:

E, [2011-06-01T07:01:39.806164 #21751] ERROR -- : Read error: #<ThreadError: deadlock; recursive locking>
E, [2011-06-01T07:01:39.806316 #21751] ERROR -- : /var/www/shared/bundle/ruby/1.9.1/gems/rack-1.3.0/lib/rack/lock.rb:33:in `lock'
/var/www/shared/bundle/ruby/1.9.1/gems/rack-1.3.0/lib/rack/lock.rb:33:in `call'
/var/www/shared/bundle/ruby/1.9.1/gems/rack-cache-1.0.2/lib/rack/cache/context.rb:132:in `forward'
/var/www/shared/bundle/ruby/1.9.1/gems/rack-cache-1.0.2/lib/rack/cache/context.rb:243:in `fetch'
/var/www/shared/bundle/ruby/1.9.1/gems/rack-cache-1.0.2/lib/rack/cache/context.rb:181:in `lookup'
/var/www/shared/bundle/ruby/1.9.1/gems/rack-cache-1.0.2/lib/rack/cache/context.rb:65:in `call!'
/var/www/shared/bundle/ruby/1.9.1/gems/rack-cache-1.0.2/lib/rack/cache/context.rb:50:in `call'
/var/www/shared/bundle/ruby/1.9.1/gems/railties-3.1.0.rc1/lib/rails/rack/content_length.rb:16:in `call'
/var/www/shared/bundle/ruby/1.9.1/gems/hoptoad_notifier-2.4.10/lib/hoptoad_notifier/user_informer.rb:12:in `call'
/var/www/shared/bundle/ruby/1.9.1/gems/railties-3.1.0.rc1/lib/rails/engine.rb:438:in `call'
/var/www/shared/bundle/ruby/1.9.1/gems/railties-3.1.0.rc1/lib/rails/railtie/configurable.rb:28:in `method_missing'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:545:in `process_client'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:623:in `block in worker_loop'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:621:in `each'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:621:in `worker_loop'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:509:in `block (2 levels) in spawn_missing_workers'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:507:in `fork'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:507:in `block in spawn_missing_workers'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:503:in `each'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:503:in `spawn_missing_workers'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:516:in `maintain_worker_count'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn/http_server.rb:166:in `start'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/lib/unicorn.rb:30:in `run'
/var/www/shared/bundle/ruby/1.9.1/gems/unicorn-3.6.2/bin/unicorn:120:in `<top (required)>'
/var/www/shared/bundle/ruby/1.9.1/bin/unicorn:19:in `load'
/var/www/shared/bundle/ruby/1.9.1/bin/unicorn:19:in `<main>'

The rest of my image uploads timed out and Unicorn restarted itself. I could upload again, but doing multiples at once kept causing this error (and much more frequently after the first time it happened--I could sometimes get it to deadlock when uploading two files at the same time).

Here's the gist of the flow of the app:

1. Client uploads a file

2. I take the tempfile created by Rack and set it as the file attribute of my Image model

3. Then I do this:

   tempfile = Tempfile.new(['prefix','.jpg'])
   tempfile << File.read(self.file.tempfile)
   modify(tempfile, options)
   self.width, self.height = get_size(tempfile) if options[:save_dimensions]
   upload(tempfile, options[:prefix]+remote_filename)

• modify is the method that farms out to ImageMagick with a command like convert -resize "250x250>" #{tempfile.path})
• get_size calls identify #{tempfile.path} to get the dimensions of the image
• upload sends the image up to S3

There are a few different places in there where things could go wrong (wrong image format for ImageMagick, S3 not responding) but in all of those cases shouldn't the request then throw an error or time out and then rack will release any locks?

[raggi]

I believe this is fixed in rack 1.3.0, have you tried it against 1.3.0 release rather than 1.3.0.beta2?

[raggi]

I'd also like to ask why you're using unicorn for slow requests like this? surely you want to be using rainbows?

[cannikin]

Yeah, I'm using 1.3.0. I've found that the ImageMagick command I'm running seems to freak out regularly and lock up so I'm going to switch over to freeimage. And I forgot all about Rainbows!, I'll switch over to that for my upload page, thanks!