search

jejacks0n / teaspoon

Teaspoon: Javascript test runner for Rails. Use Selenium, BrowserStack, or PhantomJS.
1.43k stars 244 forks source link

#generate_report sometimes fails with NoMethodError: undefined method `exitstatus' for nil:NilClass #475

Closed baburdick closed 8 years ago

baburdick commented 8 years ago 
E, [2016-04-11T21:16:47.045563 #74293] ERROR -- : reaped #<Process::Status: pid 74318 SIGSEGV (signal 11)> worker=unknown
rake aborted!
NoMethodError: undefined method `exitstatus' for nil:NilClass
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:37:in `block in check_thresholds'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:54:in `call'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:54:in `block in input_path'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:51:in `input_path'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:35:in `check_thresholds'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:63:in `resolve_coverage'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:53:in `on_result'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:30:in `notify_formatters'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:16:in `process'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:28:in `block in run_specs'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `each'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `block in run'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `popen'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `run'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:27:in `run_specs'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:55:in `run_specs'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:44:in `block in execute_without_handling'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `each'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `inject'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `execute_without_handling'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:27:in `execute'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:23:in `failures?'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/gems/teaspoon-1.1.5/lib/tasks/teaspoon.rake:14:in `block in <top (required)>'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/bin/ruby_executable_hooks:15:in `eval'
/Users/me/.rvm/gems/ruby-2.2.4@my_app/bin/ruby_executable_hooks:15:in `<main>'
I, [2016-04-11T21:16:47.359501 #74293]  INFO -- : reaped #<Process::Status: pid 74421 exit 0> worker=unknown
jejacks0n commented 8 years ago

Please provide more information. What's the pattern? Is it completely arbitrary, or can you figure out how to reproduce it?

baburdick commented 8 years ago

No rhyme or reason so far. It happens with both Ruby 2.2.4 and Ruby 2.1.8. I can run it successfully (but never reliably):

$ bundle exec teaspoon --suite=default
Starting the Teaspoon server...
I, [2016-04-12T20:16:11.932885 #68933]  INFO -- : listening on addr=127.0.0.1:55455 fd=17
I, [2016-04-12T20:16:11.933000 #68933]  INFO -- : worker=0 spawning...
I, [2016-04-12T20:16:11.934859 #68933]  INFO -- : master process ready
I, [2016-04-12T20:16:11.936008 #68957]  INFO -- : worker=0 spawned pid=68957
I, [2016-04-12T20:16:11.936441 #68957]  INFO -- : worker=0 ready
Teaspoon running default suite at http://127.0.0.1:55455/teaspoon/default
....

Finished in 0.06000 seconds
4 examples, 0 failures
I, [2016-04-12T20:16:39.933504 #68933]  INFO -- : reaped #<Process::Status: pid 68958 exit 0> worker=unknown

=============================== Coverage summary ===============================
Statements   : 19.65% ( 190/967 )
Branches     : 2.45% ( 5/204 )
Functions    : 23.75% ( 76/320 )
Lines        : 19.77% ( 190/961 )
================================================================================

... And then immediately after that, run it again, and produce the failure (again, never reliably):

$ bundle exec teaspoon --suite=default
Starting the Teaspoon server...
I, [2016-04-12T20:16:57.290987 #69086]  INFO -- : listening on addr=127.0.0.1:55621 fd=17
I, [2016-04-12T20:16:57.291119 #69086]  INFO -- : worker=0 spawning...
I, [2016-04-12T20:16:57.292950 #69086]  INFO -- : master process ready
I, [2016-04-12T20:16:57.294173 #69110]  INFO -- : worker=0 spawned pid=69110
I, [2016-04-12T20:16:57.294616 #69110]  INFO -- : worker=0 ready
Teaspoon running default suite at http://127.0.0.1:55621/teaspoon/default
....

Finished in 0.07200 seconds
4 examples, 0 failures
I, [2016-04-12T20:17:23.214124 #69086]  INFO -- : reaped #<Process::Status: pid 69111 exit 0> worker=unknown
I, [2016-04-12T20:17:23.253225 #69086]  INFO -- : reaped #<Process::Status: pid 69205 exit 0> worker=unknown
/Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:61:in `generate_report': undefined method `exitstatus' for nil:NilClass (NoMethodError)
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:25:in `block (2 levels) in generate_reports'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:24:in `each'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:24:in `block in generate_reports'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:54:in `call'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:54:in `block in input_path'
    from /Users/me/.rvm/rubies/ruby-2.1.8/lib/ruby/2.1.0/tmpdir.rb:88:in `mktmpdir'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:51:in `input_path'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:22:in `generate_reports'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:62:in `resolve_coverage'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:53:in `on_result'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:30:in `notify_formatters'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:16:in `process'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:28:in `block in run_specs'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `each'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `block in run'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `popen'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `run'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:27:in `run_specs'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:55:in `run_specs'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:44:in `block in execute_without_handling'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `each'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `inject'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `execute_without_handling'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:27:in `execute'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:23:in `failures?'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/command_line.rb:15:in `initialize'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/bin/teaspoon:6:in `new'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/bin/teaspoon:6:in `<top (required)>'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/teaspoon:23:in `load'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/teaspoon:23:in `<main>'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/ruby_executable_hooks:15:in `eval'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/ruby_executable_hooks:15:in `<main>'

In the failure case, it seems there are always two reaped processes. In the successful runs, only one. But the text-summary can succeed or fail:

$ bundle exec teaspoon --suite=default
Starting the Teaspoon server...
I, [2016-04-12T20:23:36.673327 #69608]  INFO -- : listening on addr=127.0.0.1:56065 fd=17
I, [2016-04-12T20:23:36.673455 #69608]  INFO -- : worker=0 spawning...
I, [2016-04-12T20:23:36.675464 #69608]  INFO -- : master process ready
I, [2016-04-12T20:23:36.676748 #69633]  INFO -- : worker=0 spawned pid=69633
I, [2016-04-12T20:23:36.677231 #69633]  INFO -- : worker=0 ready
Teaspoon running default suite at http://127.0.0.1:56065/teaspoon/default
....

Finished in 0.06000 seconds
4 examples, 0 failures
I, [2016-04-12T20:24:02.652953 #69608]  INFO -- : reaped #<Process::Status: pid 69634 exit 0> worker=unknown

=============================== Coverage summary ===============================
Statements   : 19.65% ( 190/967 )
Branches     : 2.45% ( 5/204 )
Functions    : 23.75% ( 76/320 )
Lines        : 19.77% ( 190/961 )
================================================================================
I, [2016-04-12T20:24:03.450341 #69608]  INFO -- : reaped #<Process::Status: pid 69733 exit 0> worker=unknown
/Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:37:in `block in check_thresholds': undefined method `exitstatus' for nil:NilClass (NoMethodError)
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:54:in `call'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:54:in `block in input_path'
    from /Users/me/.rvm/rubies/ruby-2.1.8/lib/ruby/2.1.0/tmpdir.rb:88:in `mktmpdir'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:51:in `input_path'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/coverage.rb:35:in `check_thresholds'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:63:in `resolve_coverage'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:53:in `on_result'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:30:in `notify_formatters'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/runner.rb:16:in `process'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:28:in `block in run_specs'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `each'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `block in run'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `popen'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:35:in `run'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/driver/phantomjs.rb:27:in `run_specs'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:55:in `run_specs'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:44:in `block in execute_without_handling'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `each'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `inject'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:42:in `execute_without_handling'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:27:in `execute'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/console.rb:23:in `failures?'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/lib/teaspoon/command_line.rb:15:in `initialize'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/bin/teaspoon:6:in `new'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/gems/teaspoon-1.1.5/bin/teaspoon:6:in `<top (required)>'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/teaspoon:23:in `load'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/teaspoon:23:in `<main>'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/ruby_executable_hooks:15:in `eval'
    from /Users/me/.rvm/gems/ruby-2.1.8@my_app/bin/ruby_executable_hooks:15:in `<main>'

I have these possibly relevant settings in my spec/teaspoon_env.rb:

config.use_coverage = true
coverage.reports = %w[ text-summary html ]
coverage.ignore << %r{/app/assets/javascripts/(?:app/views|templates)/}

# Early stage thresholds:
coverage.statements = 19.65
coverage.branches   = 2.45
coverage.functions  = 23.75
coverage.lines      = 19.77

Looking back at this, it appears there are two similar errors, one in #generate_report and one in #check_thresholds. In each case they're trying to send #exitstatus to a non-existent exit status code.

jejacks0n commented 8 years ago

and it doesn't happen when you don't use coverage?

baburdick commented 8 years ago

To be clear, config.use_coverage = true precedes the config.coverage do |coverage| block. The other config lines are inside that block. I blurred that distinction when keying my last post here.

baburdick commented 8 years ago

Correct. Can't make it happen when I disable coverage.

jejacks0n commented 8 years ago

no worries. =) So if it's only happening when generating reports, my best guess would be that it's an issue with how Istanbul is processing your javascript (or not processing). Teaspoon shells out to Istanbul and off loads that stuff and awaits a response.. you can find the relevant line here:

https://github.com/modeset/teaspoon/blob/master/lib/teaspoon/coverage.rb#L61

You can see it's using $?.exitstatus, which apparently is nil. I'd drop in a pry (or otherwise debug) on that line and see what the output is like from Istanbul. Potentially you have a bad install, or outdated version or something?

baburdick commented 8 years ago

If I disable text-summary and the coverage thresholds, I can avoid the error.

jejacks0n commented 8 years ago

It's the only thing that makes sense unless you have some threaded setup or something -- and I'm not even sure about if that would cause an issue or not.

baburdick commented 8 years ago

Yep. If I enable either of them, I get intermittent errors.

May I suggest gracefully carrying on in the face of lost process adversity?

    def check_thresholds(&block)
      args = threshold_args
      return if args.blank?
      input_path do |input|
        result = %x{#{@executable} check-coverage #{args.join(" ")} #{input.shellescape} 2>&1}
        begin
          return if $?.exitstatus == 0
        rescue NoMethodError
          return
        end
        result = result.scan(/ERROR: .*$/).join("\n").gsub("ERROR: ", "")
        block.call(result) unless result.blank?
      end
    end
    def generate_report(input, format)
      output_path = File.join(@config.output_path, @suite_name)
      result = %x{#{@executable} report --include=#{input.shellescape} --dir #{output_path} #{format} 2>&1}
      begin
        return result.gsub("Done", "").gsub("Using reporter [#{format}]", "").strip if $?.exitstatus == 0
      rescue NoMethodError
        # Fall through to the following `raise`
      end
      raise Teaspoon::DependencyError.new("Unable to generate #{format} coverage report:\n#{result}")
    end
baburdick commented 8 years ago

(The only changes above are the begin;rescue;end blocks around the calls to #exitstatus.)

jejacks0n commented 8 years ago

That doesn't seem like a good solution. You'd be here with the same issue, different result.. e.g. "Teaspoon arbitrarily fails to generate my text reports on some runs". =)

What you probably should do is figure out why Istanbul fails to return a result sometimes. I'm trying to help you get to the root cause, which seems to only be afflicting you thus far.

baburdick commented 8 years ago

It appears to be a timing issue. If I rescue the NoMethodErrors and sleep 2 before I reference the result, I can see a proper result, but still can't get the exit status code via $?. Somehow the value of $? is either not yet set, or lost at the time we reference it. It's likely that my very busy laptop exposes this weakness in using %x{} and $?. Perhaps it could be replicated by stuffing the RAM of a VM full of apps, and heavily loading it before running bundle exec teaspoon --suite=default. And I may be the only one in that condition. :-(

Fortunately, there's an alternate way to shell out and get STDOUT, STDERR, and the exit status code, in one operation, while cleanly closing handles: use Open3.capture2e (http://stackoverflow.com/questions/690151/getting-output-of-system-calls-in-ruby/20001569#20001569).

Implementing the methods with Open3.capture2e looks like this:

    def check_thresholds(&block)
      args = threshold_args
      return if args.blank?
      input_path do |input|
        result, st = Open3.capture2e [@executable, "check-coverage", args.join(" "), input.shellescape].join(" ")
        return if st.exitstatus == 0
        result = result.scan(/ERROR: .*$/).join("\n").gsub("ERROR: ", "")
        block.call(result) unless result.blank?
      end
    end
    def generate_report(input, format)
      output_path = File.join(@config.output_path, @suite_name)
      result, st = Open3.capture2e [@executable, "report", "--include=#{input.shellescape}", "--dir #{output_path}", format].join(" ")
      return result.gsub("Done", "").gsub("Using reporter [#{format}]", "").strip if st.exitstatus == 0
      raise Teaspoon::DependencyError.new("Unable to generate #{format} coverage report:\n#{result}")
    end

I could not get it to fail using this alternate implementation. You could hardcode the joining of the arguments to Open3.capture2e. That's just an artifact of my testing.

baburdick commented 8 years ago

Forgot to note: you need this at the top of coverage.rb:

require "open3"
baburdick commented 8 years ago

Dove a bit deeper into how Open3.capture2e relies ultimately on Process.spawn. So I can now simplify the args. Pull request coming shortly.

baburdick commented 8 years ago

See modeset/teaspoon#476