Rspec formatter suddenly and intermittently stops output to STDOUT

[synth]

I just spent 3 days debugging this, and I'm still not sure what's going on, but here's the story:

The symptom is that my rspec feature suite(using capybara-webkit) would run and just stop suddenly and randomly somewhere in the suite. I would see a bunch of a passing "."'s and then all of a sudden the shell prompt with no other output. It seemed like the process was dieing for some reason. But then I realized that at a certain point, the output would stop but the test.rb logs would keep going. I thought I was in some infinite redirect loop or something, and after 3 days, I finally realized the tests were completing it was just the output that was stopping.

I then changed my test suite to output to a file and through tailing the file, I could see all the output and see my tests fully passing. This occurs with every formatter available in rspec-core(json, progress, html, etc).

What's weird about this issue is that I feel it has something to do with threading or a race condition. Our application has some pages that load in content blocks asynchronously, we call these "pagelets"(a la facebook's pagelet architecture). Some pages load in multiple pagelets, each via an ajax call. The symptom of losing output only occurs on tests that visit a page that load in multiple pagelets. Pages that load in only one pagelet do not experience this issue.

Additionally, the issue does not occur when running an individual test in isolation, but only when in suite and occurs a different points in the suite randomly.

As I said, the workaround is to output to a file, but it'd be nice to understand what's really going on here and fix this properly.

Another fact, is that this was noticed after upgrading my application from rails 3.2.17 to 4.1.0. By doing this, rspec was also upgraded, although seemingly minor(see below)

Previous working versions:

rspec (2.14.1)
rspec-core (2.14.7)
rspec-expectations (2.14.4)
rspec-mocks (2.14.4)
rspec-rails (2.14.1)
capybara (2.2.1)
capybara-webkit (1.1.0)

Current wonky versions

rspec (2.14.1)
rspec-core (2.14.8)
rspec-expectations (2.14.5)
rspec-mocks (2.14.6)
rspec-rails (2.14.2)
capybara (2.1.0)
capybara-webkit (~> 1.1.1)!

I realize this is super difficult to assess, but maybe someone has some particular knowledge or good questions that I can go and continue to diagnose this super weird behavior.

[synth]

I wonder if its related to this: http://stackoverflow.com/questions/21550514/cucumber-tests-suddenly-stops

[myronmarston]

Hmm, that's pretty odd. As you say, hard for us to troubleshoot w/o an example repo we can play with.

Can you isolate it to something you can put on github so we can clone and play with it? If not that, my suggestion is to create a custom formatter that prints to a file and as each example starts and completes also outputs the inspect output of STDOUT/$stdout/@output so we can see if those are being mutated somehow.

[myronmarston]

Also, you mention that you upgraded rails and rspec at the same time. It'd be good to figure out which upgrade triggers the problem. Can you downgrade your rspec gems to the original versions (except for rspec-rails)? If that demonstrates it's rspec at fault you can try upgrading all but rspec-core (and then rspec-core separately) to see if it's rspec-core at fault (it's the most likely candidate). If it is, then the next step is to use git bisect to see what commit triggered this bug. You can do that by using a local checkout of rspec-core (using bundler's :path option) and running git bisect against that between the good version and bad version.

[synth]

Ok, good suggestions! I"m going to start with the custom formatter. I've already tried creating an isolated repo without luck of reproducing the issue(new app, but same Gemfile and same spec_helper.rb files). I'll post back when I can get some more info

[JonRowe]

Do you split your tests into javascript and not javascript? It could be capybara-webkit related.

[synth]

@JonRowe well, everything in /features is using capybara-webkit, the other tests are just unit tests. I've considered capybara-webkit to be the culprit; I haven't really dug through it yet, but what is the relationship of capybara-webkit to the formatters? Could this be a thread safety issue?

[JonRowe]

Capybara by default configures drivers to use rack-test for non javascript specs, and to boot an app for javascript ones, which utilises forking. My theory is that is causing something to go awry with std out.

[synth]

I've created a custom formatter subclassed off the progress formatter, and I've inspected the object ids, instance variables(which I guess there are none for IO objects) and whether the stream was closed. Nothing seemed to jump out at me as everything looked normal(ie @output was equivalent to STDOUT in all respects through all the tests)

[synth]

Ok, so much hair pulling later, here's some new evidence. The output seems to drop out at some point between the #example_started and #example_passed calls in the formatter. Process.pid, Process.ppid, and Thread.current all remain the same, however, the #stat call on each io object has been mutated:

#example_started(example)
STDOUT.stat # <File::Stat dev=0x1c976248, ino=8195, mode=020620, nlink=1, uid=501, gid=4, rdev=0x10000007, size=0, blksize=131072, blocks=0, atime=2014-05-07 20:09:52 -0700, mtime=2014-05-07 20:09:52 -0700, ctime=2014-05-07 20:09:52 -0700>
STDERR.stat # <File::Stat dev=0x1c976248, ino=8195, mode=020620, nlink=1, uid=501, gid=4, rdev=0x10000007, size=0, blksize=131072, blocks=0, atime=2014-05-07 20:09:52 -0700, mtime=2014-05-07 20:09:53 -0700, ctime=2014-05-07 20:09:53 -0700>
@output.stat # <File::Stat dev=0x1c976248, ino=8195, mode=020620, nlink=1, uid=501, gid=4, rdev=0x10000007, size=0, blksize=131072, blocks=0, atime=2014-05-07 20:09:52 -0700, mtime=2014-05-07 20:09:53 -0700, ctime=2014-05-07 20:09:53 -0700>

#example_passed(example)
STDOUT.stat # <File::Stat dev=0x1c976248, ino=316, mode=020666, nlink=1, uid=0, gid=0, rdev=0x3000002, size=0, blksize=131072, blocks=0, atime=2014-05-07 14:53:36 -0700, mtime=2014-05-07 20:09:53 -0700, ctime=2014-05-07 20:09:53 -0700>
STDERR.stat # <File::Stat dev=0x1c976248, ino=316, mode=020666, nlink=1, uid=0, gid=0, rdev=0x3000002, size=0, blksize=131072, blocks=0, atime=2014-05-07 14:53:36 -0700, mtime=2014-05-07 20:09:56 -0700, ctime=2014-05-07 20:09:56 -0700>
@output.stat # <File::Stat dev=0x1c976248, ino=316, mode=020666, nlink=1, uid=0, gid=0, rdev=0x3000002, size=0, blksize=131072, blocks=0, atime=2014-05-07 14:53:36 -0700, mtime=2014-05-07 20:09:56 -0700, ctime=2014-05-07 20:09:56 -0700>

So, analyzing this is a bit above my paygrade, but you can clearly see the inode has changed and the uid, gid, and rdev attributes have changed. What this means and what might cause that, I don't know....

Thoughts?

[synth]

I think I found the culprit: rails/rails#13139
Commentary here: rails/activerecord-session_store#19
With monkey patch here: https://gist.github.com/tommeier/9845210

[JonRowe]

Oh Rails.

[lukeasrodgers]

Thank-you @synth! Many headaches saved.