search

romanbsd / heroku-deflater

Enable gzip compression on heroku, but don't compress images.
MIT License
358 stars 62 forks source link

app error: closed stream (IOError) #16

Closed stereoscott closed 10 years ago

stereoscott commented 10 years ago

TL;DR After updating to 0.5.3, nearly all of my asset requests were with a closed stream (IOError)

Stack trace:

18:02:51 web.1    | E, [2014-04-11T18:02:51.575456 #8280] ERROR -- : app error: closed stream (IOError)
18:02:51 web.1    | E, [2014-04-11T18:02:51.575567 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/deflater.rb:82:in `close'
18:02:51 web.1    | E, [2014-04-11T18:02:51.575685 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/deflater.rb:82:in `ensure in each'
18:02:51 web.1    | E, [2014-04-11T18:02:51.575757 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/deflater.rb:84:in `each'
18:02:51 web.1    | E, [2014-04-11T18:02:51.575925 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/lint.rb:647:in `each'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576087 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/body_proxy.rb:31:in `each'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576165 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/chunked.rb:23:in `each'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576247 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/unicorn-4.8.2/lib/unicorn/http_response.rb:60:in `http_response_write'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576339 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:582:in `process_client'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576459 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:666:in `worker_loop'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576537 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:521:in `spawn_missing_workers'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576628 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/unicorn-4.8.2/lib/unicorn/http_server.rb:140:in `start'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576747 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/unicorn-4.8.2/bin/unicorn:126:in `<top (required)>'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576822 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/bin/unicorn:23:in `load'
18:02:51 web.1    | E, [2014-04-11T18:02:51.576893 #8280] ERROR -- : /opt/boxen/rbenv/versions/2.0.0-p451/bin/unicorn:23:in `<main>'

I read up on this a bit and found a thread here (http://rubyforge.org/pipermail/mongrel-unicorn/2013-September/001874.html) that mentions:

IOError means something in the unicorn process closed the connection already, which should not happen there.

Do you have anything in your Rack app which does background processing of rack.input after the response is written?

That would be the most likely explanation...

I dug into unicorn and rack/lint a bit and both seem to call body.close on their own, which apparently is something that all rack middleware should do, but now I'm getting complaints that the steam is already closed.

I then disabled unicorn and just went through webrick. Same issue:

2014-04-11 18:38:48] ERROR IOError: closed stream
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/deflater.rb:82:in `close'
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/deflater.rb:82:in `ensure in each'
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/deflater.rb:84:in `each'
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/body_proxy.rb:31:in `each'
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/rack-1.5.2/lib/rack/handler/webrick.rb:72:in `service'
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/2.0.0/webrick/httpserver.rb:138:in `service'
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/2.0.0/webrick/httpserver.rb:94:in `run'
    /opt/boxen/rbenv/versions/2.0.0-p451/lib/ruby/2.0.0/webrick/server.rb:295:in `block in start_thread'

I think that Rack::Deflater is the middleware that is complaining because it's the middleware that runs immediately after HerokuDeflater::ServeZippedAssets:

# rake middleware
use HerokuDeflater::ServeZippedAssets
use Rack::Deflater
use HerokuDeflater::SkipBinary

I'm happy to go back to 0.5.2 but I'm curious what the cause of this issue is, and how we might solve it in a way that doesn't cause requests to fail. Happy to help in whatever way I can.

romanbsd commented 10 years ago

TL;DR - go back to 0.5.2 :) I don't quite understand this bug myself. For the best of my understanding, this is not needed: https://github.com/romanbsd/heroku-deflater/commit/10ca119b59ea3f51fc004a0b86012bad95ae98a9 , however, many people were complaining again and again, so I just did it to make them happy. I still don't know what was/is the core issue here, and unfortunately I don't have time to invest into it. Having said that, I'm still very curious to know what is going on there, and pull requests are always welcomed.

stereoscott commented 10 years ago

Very interesting indeed. Thanks for the reply and for the great plugin.