Ruby HTTP request gets “end of file reached” after 60 seconds

Over the past couple days, I’ve been trying to figure out why long-running (due to large file upload & synchronous processing time) HTTP requests to our REST API are throwing “Faraday::Error::ConnectionFailed: end of file reached” after one minute.

The client is: Ruby 1.9.3-p194, Faraday 0.8.5 using the default Net::HTTP adapter, and Hyperclient 0.3.0.

The server is: Rails 3.2.12 on Ruby 1.9.3-p194, via Apache with Passenger.

The exception looks like:

Caught Faraday::Error::ConnectionFailed: end of file reached
/usr/local/rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:141:in `read_nonblock'
/usr/local/rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:141:in `rbuf_fill'
/usr/local/rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:122:in `readuntil'
/usr/local/rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/net/protocol.rb:132:in `readline'
/usr/local/rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/net/http.rb:2562:in `read_status_line'
/usr/local/rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/net/http.rb:2551:in `read_new'
/usr/local/rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/net/http.rb:1319:in `block in transport_request'

The 60 second timing was rather mysterious for some time because:

  • The timeout option of Net::HTTP in the client had no effect, and even if it did, I would expect to see a Timeout::Error, not an EOFError.
  • Extending the Apache Timeout setting had no effect, even though Apache was sometimes logging the following error:
[ pid=6209 thr=140145517742048 file=ext/apache2/Hooks.cpp:808 time=2013-02-25 20:03:36.394 ]:
Either the visitor clicked on the 'Stop' button in the web browser, or the visitor's
connection has stalled and couldn't receive the data that Apache is sending to it. As a
result, you will probably see a 'Broken Pipe' error in this log file. Please ignore it, this
is normal. You might also want to increase Apache's TimeOut configuration option if you
experience this problem often.

We were also seeing errors in Apache’s logs like:

[ pid=13250 thr=139854544902112 file=ext/apache2/Hooks.cpp:810 time=2013-02-22 20:19:49.359 ]:
No data received from the back end application (process 27551) within 300000 msec. Either
the backend application is frozen, or your TimeOut value of 300 seconds is too low. Please
check whether your application is frozen, or increase the value of the TimeOut configuration
directive.

That means Apache wasn’t hearing anything back from Passenger/Rails for 300 seconds. Sometimes, we’d also see several Ruby (Rails) processes running for long periods of time and using a large share of the CPU. Normally, Passenger only keeps one Ruby process around, but in this case Ruby processes were remaining and even being orphaned out of the passenger-status listing. I’m still not sure why those processes were getting orphaned (was their work really taking longer than 300 seconds?).

I was eventually able to get rid of the EOF problem by bypassing the Amazon Load Balancer (aka Elastic Load Balancer or ELB) in front of our EC2 instances, which finally allowed me to pinpoint the source of the problem. Browsing the internet eventually brought me to this thread: Elastic Load Balancer: HTTP Connections time out after 60 seconds. The potential solution mentioned in the thread is that Amazon can increase the timeout on your load balancer.

While I’m happy to have a possible solution, I’m not sure why the failure occurs exactly one minute after the request initiates. I would expect that sending the body of the request would take a significant amount of time (>30 seconds), during which the connection would have traffic and therefore the ELB timeout would not start ticking. However, the software always threw the EOF error after exactly one minute.

In any case, I’m hopeful that asking for an extension to the load balancer timeout will resolve the issue. I’ll try to remember to update this post once I verify the solution.

Storing compressed blobs in Sqlite3 with Datamapper for Ruby

If you’re trying to store a blob (in my case, compressed text) into a Sqlite3 database with Datamapper and you’re running into this error:

Zlib::BufError: buffer error

Try base 64 encoding it, as hinted by this file: https://gist.github.com/721922

require 'zlib'
require 'base64'

class Foo
  include DataMapper::Resource

  property :compressed_file_content, Binary, accessor: :private

  def file_content=(str)
    @inflated_file_content = str
    deflator = Zlib::Deflate.new()
    self.compressed_file_content = Base64::encode64(deflator.deflate(@inflated_file_content, Zlib::FINISH))
    deflator.close
  end

  def file_content
    if @inflated_file_content
      @inflated_file_content
    else
      inflator = Zlib::Inflate.new
      @inflated_file_content = inflator.inflate(Base64::decode64(compressed_file_content))
      inflator.finish
      inflator.close

      @inflated_file_content
    end
  end
end

It’s as simple as that. No need to use SQLite3::Blob, for example.

Rant about Rspec-Rails

It’s stuff like this that makes Rails and its accompanying toolset a pain in the ass.

If you want a spec to check that your controller rendered a specific thing, you can’t just mock the “controller.render” method. Why? In Rails-land, apparently controller.render is so magical that your mock expectation will receive no arguments, even if your controller passed arguments to the render method. It’ll say, “got: (no args)”

Instead, you have to use the RenderTemplateMatcher with have_rendered or rendered_template (they’re the same).

That, in turn, means you have to actually let the render call complete normally, which may violate the isolation of your controller spec.

Or, if you’re like me, it gives you “ActionView::MissingTemplate: Missing template” even though the template path is accurate. This has something to do with the EmptyTemplatePathSetDecorator mentioned in the error.

At this point, you search the internet until you discover that “By default, controller specs do not render views.” However, strangely, at the same time, “NOTE: unlike rspec-rails-1.x, the template must exist.” Still no good explanation why your completely valid template isn’t being found.

So then you try adding “render_views” to your test, but find that it’s configured to only accept production templates, not template files that you have in your spec directory. So now you have to provide mocks or stubs for all the data that your chosen production template needs. So obviously that’s not a good way to go.

So then you back out the “render_views” statement, and suddenly everything’s working. What?!

Turns out that by default Rspec-Rails doesn’t actually render any templates, but it does look for the template file in the standard file paths (app/views). So don’t try to outsmart Rspec by providing your own view specifically for your spec: it won’t be able to find it.

What a waste of time.

PS: Due to limitations of ActionController::TemplateAssertions$assert_template, which RenderTemplateMatcher delegates to, you can’t check both the template and the layout at the same time. You have to use two separate statements:
response.should have_rendered template
response.should have_rendered layout: layout

Rspec-rails’s rake tasks not loaded in Rails engine

Having trouble getting the Rspec rake tasks to appear when you run “rake -T” in your Rails engine? The dummy app (which you should have if you specified –full) is not pulling in the Bundler dependencies, and as a result the rspec-rails Railtie subclass is not being created.

The fix, for me at least, is changing spec/dummy/config/application.rb line 11 or so to:

Bundler.require(*Rails.groups)

You should now have tasks such as “rake app:spec” available.

You may also need to update your root Rakefile to run the specs by default, by adding “task :default => ‘app:spec'”

Also see my issue on the railties Github

This was with Rails 3.2.8.