Cucumber tests fail with `stream closed (IOError)`

Question

We are currently upgrading our Rails app to Rails 4. In 3.2, our Cucumber (1.3.17) tests run fine (if lamentably slowly), with Capybara (2.4.4), Poltergeist (1.5.1), and PhantomJS (1.9.8) under the hood.

But in both 4.0.12 and 4.1.8, we get a stream closed (IOError) at a random point in the run:

stream closed (IOError)
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/formatter/pretty.rb:156:in `write'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/formatter/pretty.rb:156:in `puts'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/formatter/pretty.rb:156:in `step_name'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:181:in `block in send_to_all'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:179:in `each'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:179:in `send_to_all'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:173:in `broadcast'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:119:in `visit_step_name'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:112:in `block in visit_step_result'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:170:in `broadcast'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:111:in `visit_step_result'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/step_invocation.rb:43:in `visit_step_result'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/step_invocation.rb:39:in `accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:106:in `block in visit_step'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:170:in `broadcast'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:105:in `visit_step'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/step_collection.rb:19:in `block in accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/step_collection.rb:18:in `each'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/step_collection.rb:18:in `accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:100:in `block in visit_steps'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:170:in `broadcast'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:99:in `visit_steps'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:15:in `block in execute'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime.rb:83:in `block (2 levels) in with_hooks'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime.rb:99:in `before_and_after'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime.rb:82:in `block in with_hooks'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime/support_code.rb:120:in `call'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime/support_code.rb:120:in `block (3 levels) in around'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/language_support/language_methods.rb:9:in `block in around'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/language_support/language_methods.rb:97:in `call'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/language_support/language_methods.rb:97:in `execute_around'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/language_support/language_methods.rb:8:in `around'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime/support_code.rb:119:in `block (2 levels) in around'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime/support_code.rb:123:in `call'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime/support_code.rb:123:in `around'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime.rb:94:in `around'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime.rb:81:in `with_hooks'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:13:in `execute'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/scenario.rb:32:in `block in accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/scenario.rb:79:in `with_visitor'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/scenario.rb:31:in `accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:58:in `block in visit_feature_element'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:170:in `broadcast'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:57:in `visit_feature_element'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/feature.rb:38:in `block in accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/feature.rb:37:in `each'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/feature.rb:37:in `accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:27:in `block in visit_feature'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:170:in `broadcast'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:26:in `visit_feature'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/features.rb:28:in `block in accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/features.rb:17:in `each'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/features.rb:17:in `each'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/features.rb:27:in `accept'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:21:in `block in visit_features'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:170:in `broadcast'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:20:in `visit_features'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/runtime.rb:49:in `run!'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/lib/cucumber/cli/main.rb:47:in `execute!'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/gems/cucumber-1.3.17/bin/cucumber:13:in `'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/bin/cucumber:23:in `load'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/bin/cucumber:23:in `'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/bin/ruby_executable_hooks:15:in `eval'
/var/lib/jenkins/.rvm/gems/ruby-2.1.5@tallama-integration/bin/ruby_executable_hooks:15:in `'

This error is not the same as a closed stream error, which signifies that you're attempting to touch a stream after it's been closed.

No, the only time a stream closed (IOError) is thrown in all of MRI is in rb_thread_fd_close. That code in turn is only called in rb_io_close – aka when closing a file descriptor; it iterates through the other live threads and sees if any of them is waiting for the closed file descriptor. If there’s anybody waiting, it raises the stream closed error in the waiting thread. That neatly explains why the stack trace is pointing to cucumber: that’s the thread that’s waiting to write out to STDOUT, from the formatter. But we don’t have any info on who closed the file descriptor.

Since I know I'm dealing with threads here, I start to suspect timeout is killing something when it shouldn't be, but I have no way of knowing what timeout is causing the mess; I removed the one in my code but then found 35 in various gems we're using, and the issue is still occurring.

We also suspected, at some point, that one of the phantomjs processes was being killed due to low memory, and we added instrumentation to puts the current process' memory before every scenario… and the IOErrors went away, almost certainly because of timing issues. When I removed the instrumentation the errors returned.

I've also attempted to update to tip-of-tree cucumber and capybara, but neither seemed to make a difference.

Is there some clever way to track this down that I've not yet tried? Have you seen this issue and know the one-line configuration change I need to make it better? Do you have a convenient patch that removes timeout from all Ruby everywhere?

Answer 1

Ideas to try...

• Narrow the issue by trying Capybara + WebKit; Poltergeist is not thread safe (AFAIK).

• Narrow the issue by seeing if it's a Rack timeout:

  # config/initializers/timeout.rb
  Rack::Timeout.timeout = 600 
  Rack::Timeout.wait_timeout = 600 # or 0 means never timeout
  

• Temporarily turn off any tests that call to externals, such as system, sidekiq, eventmachine, delayed job, etc.

• For your idea of a patch that removes timeout from all Ruby everywhere:

  require 'timeout'
  Thread.handle_interrupt(TimeoutError => :never) {
    timeout(10){
      # TimeoutError doesn't occur here
      Thread.handle_interrupt(TimeoutError => :on_blocking) {
        # possible to be killed by TimeoutError
        # while blocking operation
      }
      # TimeoutError doesn't occur here
    }
  }
  

  See Guarding from Timeout Error

• Track the open file objects at any breakpoints you want:

  # List all open File objects.
  ObjectSpace.each_object(File) do |f|
    puts "%s: %d" % [f.path, f.fileno] unless f.closed?
  end
  
  # List the "dangling" File object which we didn't store in a variable.
  ObjectSpace.each_object(File) do |f|
    unless f.closed?  
      printf "%s: %d\n", f.path, f.fileno unless f === filehandle
    end
  end
  

  See Where does Ruby keep track of its open file descriptors