Rspec-core: Test run skipping almost all specs

[Draiken]

Hello!

For some time now I started noticing builds on our CI that were a lot faster than usual. Upon inspection I saw the tests step was significantly faster sometimes, which doesn't make sense.

Our test suite has ~7000 tests and the "fast" builds reported running different amounts of tests, but always a very small portion of the tests like ~200. This was happening randomly.

Immediately we chased down the CI environment thinking this was an environment problem, but after weeks of tests, I've managed to reproduce the same issue on my local machine, discarding the possibility that it's an environment problem.

To reproduce this I grabbed a docker image of our test runner and ran a loop locally running the same rake task multiple times and managed to get builds with different spec counts.
The task I ran was rake spec_without_rp2server which uses an exclusion pattern as you can see on the Rakefile. My only guess right now is that it might be the problem

Here is our setup:
Ruby version: 2.1.10
RSpec versions:

• rspec (3.7.0)
• rspec-collection_matchers (1.1.3)
• rspec-core (3.7.1)
• rspec-expectations (3.7.0)
• rspec-mocks (3.7.0)
• rspec-rails (3.7.2)
• rspec-sidekiq (3.0.1)
• rspec-support (3.7.0)

Our spec helpers: https://gist.github.com/Draiken/e6f800318b5a6a77416d1385d0c58540
Our Rakefile: https://gist.github.com/Draiken/1fd9c6bffa2e8c06ce00be7c689b0dc4

[xaviershay]

hrmm, I'm not seeing anything obvious.

• This doesn't happen locally normally, only when you use the travis CI docker image?
• Have you tried disabling Simplecov?
• Are you using any custom metadata on your specs?
• Does it happen with the other rake task also?
• Per docs it looks like you're using exclude pattern correctly...

[Draiken]

This doesn't happen locally normally, only when you use the travis CI docker image?

I've managed to reproduce the issue locally running the same container as the CI. I tried running the rake task locally on my machine (without docker) and couldn't reproduce the issue so far.

Have you tried disabling Simplecov?

It's disabled by default

Are you using any custom metadata on your specs?

A few keys used to identify a group of specs and some automatic includes

Does it happen with the other rake task also?

No, it doesn't AFAIK

[amanfredi]

I just noticed something like this in our build. It seems to be related to "focusing" specs with config.filter_run :focus

It seems like one spec is being incorrectly tagged as focused and the rest of them are skipped.

Edit: Spoke too soon. Someone committed a spec with "fit" to focus it 👎

[Draiken]

I'm pretty sure it's the filtering as I never seen this happen with all specs running. This still happens with us to this date, but I don't have time to try to fix it myself :slightly_frowning_face:

[JonRowe]

You can use --dry-run to see what specs would run without running them, an introspection into the on your config for files_to_run will show whats files are at least being attempted to be run.

You can simulate your exclusion filer with:

$ ruby -e 'puts Dir["{spec/rp2_server/**/*_spec.rb}"]'

Which should return the same each time (if it doesn't theres a problem with your directory structure.

You should check your default path is spec (default_path off your configuration) and that your directory structure is stable and doesn't some how contain the path above.

[Draiken]

That was my initial thought: files are not there or in the wrong place.
I added steps to my spec run to list files, file trees and all that. It was always the same whether all specs ran or not.
I'll give this another go running with --dry-run and see if I manage to get the error to happen again.

[JonRowe]

Sorry, perhaps I didn't explain that clearly, looking at files_to_run shows what RSpec can actually see after processing all the options, if there are files in there that are not being run in the missing spec runs then there is a bug elsewhere in RSpec, or other filtering going on.

If there are files missing then it's an interaction in the filter / glob process we need to look at.

[Draiken]

While attempting to inspect RSpec.configuration.files_to_run I noticed one of the rake tasks wasn't requiring spec_helper. Not sure if this was the issue, but I switched the tasks to use tags and used config.define_derived_metadata to set them.

Hopefully this was just a stupid mistake of the CI not including --require spec_helper that was normally on .rspec

I'll report back after testing this further

[enkessler]

I am also encountering this problem. 2/3 of my test suite is not getting run by RSpec. It seems to have something to do with the nesting level of the spec file. The pattern that I use to find the spec files consistently finds every file no matter where the suite is run (locally on Windows, AppVeyor, and Travis CI) or nesting level used but RSpec misses tests in my non-windows/Travis environments depending on how the tests are nested.

AppVeyor, original nesting (all found):
https://ci.appveyor.com/project/enkessler/cuke-linter/builds/22820753/job/4gmwebpi6srxwbr8
AppVeyor, adjusted nesting (all found):
https://ci.appveyor.com/project/enkessler/cuke-linter/builds/22824294/job/kbritbtbd778bwjc
Travis CI, original nesting (missing deeply nested specs):
https://travis-ci.org/enkessler/cuke_linter/jobs/501779688
Travis CI, adjusted nesting (all found):
https://travis-ci.org/enkessler/cuke_linter/jobs/501850822

[JonRowe]

@enkessler I've had a very brief look at your issue, you have _specs.rb files, these won't match the _spec.rb pattern.

[enkessler]

The _specs.rb files aren't meant to be picked up by the pattern. Those files contain shared examples that are pulled in via rspec_env.rb, not regular files full of tests that are directly run like the _spec.rb files. So, that 's expected. Further, if that were the problem, then it still wouldn't explain why moving the regular spec files up one nesting level makes them work.

[JonRowe]

My apologies, it was a very brief look. In order to investigate further I suggest you use my advice above. E.g. Look at what RSpec.configuration.files_to_run actually contains during a problematic run.

[enkessler]

Done: https://travis-ci.org/enkessler/cuke_linter/jobs/502360830

If there are files missing then it's an interaction in the filter / glob process we need to look at.

That's what it looks like, yeah.

[JonRowe]

There can be some weirdness when you're running from Rake tasks, which is why our default pattern is a bitt different, I'd investigate there if I were you

[enkessler]

I _really_ do not want to have to fork this repo, stick a bunch of debugging code in it, and make my CI builds use the fork in order to see if I can find a problem.

[JonRowe]

I can understand that, luckily I don't think you have to, try setting your pattern to:

rspec_args = '--pattern testing/rspec/spec/**{,/*/**}/*_spec.rb'

From memory our default pattern does this to work around issues like this. (e.g. its a configuration issue, not a bug).

[enkessler]

When in doubt, add more wildcards? ;)

[enkessler]

Does RSpec not use the same pattern syntax as Dir.glob? Is **/* not the correct notation for making the pattern recursive?

[enkessler]

If I use that pattern (testing/rspec/spec/**{,/*/**}/*_spec.rb), I now get twice as many files found by Ruby (duplicates, it looks like) but the correct number of files found by RSpec for Linux and Windows. In OSX, it's all file loading errors.

Linux: https://travis-ci.org/enkessler/cuke_linter/jobs/502856425
OSX: https://travis-ci.org/enkessler/cuke_linter/jobs/502856430
Windows: https://ci.appveyor.com/project/enkessler/cuke-linter/build/job/78iry5ms6fqvh4yj

I know that you say this is a configuration issue and not a bug but it feels a lot like a bug.

[JonRowe]

If you can produce a minimal reproduction of this issue using only RSpec, I'll be happy to look into it further with the assumption the fault lies in the runner, but so far all of your build output indicates the problem lies within the Rake config you have.

I'm afraid my time is very limited at the moment and I simply don't have enough of it to go through your Rake setup to find out whats going on.

In the mean time I suggest you look at RSpec.configuration.files_to_run (don't use Dir.glob its not a direct parallel to what we do, see lib/rspec/core/configuration.rb) when using various patterns, and try invoking RSpec directly rather than through your rake tasks.

[enkessler]

Okay...so what kind of patterns are expected? Normal Ruby regular expressions? Some platform specific shell pattern? What? I don't see any documentation anywhere explaining what syntax to use.

[JonRowe]

I just mean don't use the code Dir.glob its a shell glob for your platform.

[enkessler]

But what should I use? There is no instruction manual or examples and 'go read the code' is horrible advice to give to a user.

[JonRowe]

To input a pattern, which will depend on your file system, use (from the command line):
rspec --pattern <pattern>
and then:
puts RSpec.configuration.files_to_run
in your spec_helper.rb or first loaded / other configuration file to debug which files are loaded.

This is documented with examples here:

https://relishapp.com/rspec/rspec-core/v/3-8/docs/command-line/pattern-option

For pattern formats may I recommend https://en.wikipedia.org/wiki/Glob_%28programming%29

You can find more of our documentation here http://rspec.info/documentation/

Please remember this is an open source project maintained by volunteers.

[enkessler]

Hey, there it is. The very last example does indicate that glob unions are acceptable, although it is not necessarily clear that glob syntax is supposed to be used at all times (as opposed to unions being some sort of exception).

FYI: the Relish documentation does not line up with the documentation in rspec --help

-P, --pattern PATTERN Load files matching pattern (default: "spec/**/*_spec.rb").

To input a pattern, which will depend on your file system

...why? Why use platform specific functionality rather than something portable like the built in Ruby stuff?

Finally, I know that this is an open source project run and maintained by volunteers. It is also literally the most widely used gem in the entire Ruby ecosystem. So please forgive me if my expectations are a little higher than for any other random library. Your responsiveness has been appreciated. My annoyance stems primarily from how much effort it took to reach the final answer of 'our patterns are different'. This is a Happy Path, not some edge case. It shouldn't be this hard to figure out how to use it.

[JonRowe]

...why? Why use platform specific functionality rather than something portable like the built in Ruby stuff?

Ruby is platform specific, when it comes to the APIs that interact with the file system, just like you'd expect it to be, C:\blah obviously is a windows path and /path/to/ is a POSIX one, thats all I mean, I wouldn't expect the exact same behaviour between Windows and POSIX when it comes to things like this.

[enkessler]

Ruby is platform specific when it relies on platform specific stuff like fork, yeah, but for most things it's not. And it tends to call out the platform specific stuff so that people don't use it if they are trying to write portable code. Dir.glob works consistently across platforms. That would seem a better choice.

The point of having a high level language is to abstract away all the fiddly bits if I don't need to deal with them. The File class does a pretty good job of letting me not worry about the exact style of my files paths, regardless of what platform I'm running on. That, or it's because I use / everywhere and Ruby makes sure that it keeps working even on Windows. Which is kind of my point.

[JonRowe]

There are platform specific edge cases in paths in Rubies File library when it comes to patterns, we attempt to work around them for you.

[JonRowe]

This is how we load files in order to maximise compatibility:

      def get_matching_files(path, pattern)
        raw_files = Dir[file_glob_from(path, pattern)]
        raw_files.map { |file| File.expand_path(file) }.sort
      end

      def file_glob_from(path, pattern)
        stripped = "{#{pattern.gsub(/\s*,\s*/, ',')}}"
        return stripped if pattern =~ /^(\.\/)?#{Regexp.escape path}/ || absolute_pattern?(pattern)
        File.join(path, stripped)
      end

      if RSpec::Support::OS.windows?
        # :nocov:
        def absolute_pattern?(pattern)
          pattern =~ /\A[A-Z]:\\/ || windows_absolute_network_path?(pattern)
        end

        def windows_absolute_network_path?(pattern)
          return false unless ::File::ALT_SEPARATOR
          pattern.start_with?(::File::ALT_SEPARATOR + ::File::ALT_SEPARATOR)
        end
        # :nocov:
      else
        def absolute_pattern?(pattern)
          pattern.start_with?(File::Separator)
        end
      end

[enkessler]

Based on that code, it _is_ using the standard Dir.glob except that it tweaks the pattern before applying it. Given that the glob pattern that I am using works fine before I hand it to RSpec but stops working fine after RSpec tweaks it, I'm inclined to still call this a bug.

[JonRowe]

@enkessler If you can reproduce this without any other dependencies I will look into it further. What I need is a repo that contains:

• spec files (preferably "noop" ones as patterns only affect file loading)
• rspec config
• a pattern that misses files.

If it only occurs via Rake or any other dependency only then the bug is not in RSpec.

[enkessler]

Here you go: https://github.com/enkessler/rspec_investigation

Plain old RSpec with 6 files, one test each, and a nesting structure.

https://travis-ci.org/enkessler/rspec_investigation/jobs/506601833

Running RSpec on the testing directory runs them all. Globing with the perfectly normal recursive pattern testing/rspec/spec/**/*_spec.rb finds them all. Running RSpec with said pattern only finds the topmost two.

[JonRowe]

Thanks, the problem in your reproduction lies in the shell. Your command:

rspec --pattern testing/rspec/spec/**/*_spec.rb

Is interpolated by the shell before it gets to RSpec as two files, so the command executed is:

rspec --pattern testing/rspec/spec/integration/baz_spec.rb testing/rspec/spec/unit/baz_spec.rb -f d

you can replicate this with:

ruby -e "puts ARGV" testing/rspec/spec/**/*_spec.rb

Wrapping the pattern in " produces the correct result:

rspec --pattern "testing/rspec/spec/**/*_spec.rb" -f d

I would thus suggest in your original application, that whatever is invoking RSpec is not wrapping the pattern in quotes beforehand. I'd happily accept a PR improving the documentation here!

[Draiken]

I'm guessing this wouldn't apply for patterns added on a Rake task, right?
We had this issue using these tasks:

  desc "Run specs (without RP2Server)"
  RSpec::Core::RakeTask.new(:spec_without_rp2server) do |task|
    task.rspec_opts = "--format progress --color"
    task.exclude_pattern = 'spec/rp2_server/**/*_spec.rb'
  end

  desc "Run specs for the RP2Server"
  RSpec::Core::RakeTask.new(:spec_rp2server) do |task|
    task.rspec_opts = "--format progress --color"
    task.pattern = ['spec/rp2_server/**/*_spec.rb']
  end

The first spec would occasionally take 1 minute instead of the usual 9 minutes running a minuscule fraction of the suite.

I was never able to figure out a reproducible state for this, and unfortunately had to move on to other tasks.

Perhaps when rake is expanding to the system call, it doesn't quote the paths?

[Draiken]

I cloned the testing repo and tested adding rake tasks on top of it. Weirdly enough the exclude pattern didn't work:

require 'rspec/core/rake_task'

RSpec::Core::RakeTask.new(:spec_exclude) do |task|
  task.exclude_pattern = 'testing/rspec/spec/unit/**/*_spec.rb'
end

RSpec::Core::RakeTask.new(:spec_pattern) do |task|
  task.pattern = ['testing/rspec/spec/**/*_spec.rb']
end

Running rake spec_exclude resulted in:

/home/felipe/.rvm/rubies/ruby-2.5.1/bin/ruby -I/home/felipe/.rvm/gems/ruby-2.5.1/gems/rspec-support-3.8.0/lib:/home/felipe/.rvm/gems/ruby-2.5.1/gems/rspec-core-3.8.0/lib /home/felipe/.rvm/gems/ruby-2.5.1/gems/rspec-core-3.8.0/exe/rspec --pattern spec/\*\*\{,/\*/\*\*\}/\*_spec.rb  --exclude-pattern testing/rspec/spec/unit/\*\*/\*_spec.rb
No examples found.


Finished in 0.00021 seconds (files took 0.03682 seconds to load)
0 examples, 0 failures

Running it on the CLI:

rspec testing/ --exclude-pattern 'testing/rspec/spec/unit/**/*_spec.rb'
...

Finished in 0.00177 seconds (files took 0.06023 seconds to load)
3 examples, 0 failures

The spec_pattern task ran successfully with 6 specs.

[JonRowe]

@Draiken You can see the command called, the rake tasks escapes the glob differently, and in your former example is sending the default pattern... er by default...

[enkessler]

@JonRowe Adding the quotes did solve the problem for me. When going through a Rake task, the problem only presented in CI. With only RSpec the problem presented everywhere. With the quotes, it is now working correctly everywhere.

@Draiken That being said, your case may still be different because whereas my problem was the command line fiddling with the pattern before it got to RSpec, you seem to be configuring RSpec directly via the Rake task. Presumably the shell isn't involved in any hand-offs between Rake and RSpec, so maybe in your case the problem really is in the RSpec Rake task and some inconsistency between it and RSpec proper.

[JonRowe]

Presumably the shell isn't involved in any hand-offs between Rake and RSpec

Rake executes RSpec via the shell, you can see the pattern escaped in a different way (backslashes inserted) in the command Rake runs.

[Draiken]

Ugh, this is confusing. I attempted to set the pattern to remove the default one on the task with excluded pattern, but then RSpec apparently expands the pattern and generates the command with all the files as arguments, rendering the exclusion pattern useless. I suppose this is slightly off topic.

My biggest worry is the seemingly random nature of the problem for us. We still suffer from the occasional CI run skipping specs and I have a nagging feeling that this isn't as simple as wrong patterns or a bug in the widely used CLI arguments. Unfortunately I was never able to isolate a reproducible environment :disappointed:

[JonRowe]

RSpec apparently expands the pattern and generates the command with all the files as arguments

No thats the shell expanding the unescaped glob. Not RSpec.

[JonRowe]

@Draiken do you have example output I can look at? I may be able to help further.

[Draiken]

@JonRowe Here is the log output from two runs. One runs normally the other skips almost every test:
https://gist.github.com/Draiken/97bb83dc64d320c7e2411bcdf55ee7a3

Same script, same environment, same rspec/rake command, same everything AFAICT.
I already attempted checking the list of files (my first thought was that somehow not all the tests were there) but they were all there.

As I explained in the issue description I thought it was the CI, but could reproduce the issue randomly on my own machine through docker (replicating the environment as much as possible).

[gucki]

FYI: I just hit the same bug. Most of the time only 90 (the number stays the same!) of 355 tests are run. It doesn't matter if I run rspec or rails spec. I also tried disabling randomizing the tests order etc. but it didn't help.

[JonRowe]

@gucki can you perform the debug steps listed above? If you can consistently replicate this using rspec alone that would be a great help in proving a bug exists here, so far the issues have surrounded external calls to the rspec cli

[gucki]

@JonRowe I just checked that all files are included:

$ rspec # ap RSpec.configuration.files_to_run
[
  [ 0] "/home/web/app/spec/controllers/doctors_spec.rb",
  [ 1] "/home/web/app/spec/controllers/kits_spec.rb",
  [ 2] "/home/web/app/spec/controllers/orders_spec.rb",
  [ 3] "/home/web/app/spec/controllers/sessions_spec.rb",
  [ 4] "/home/web/app/spec/features/doctors_spec.rb",
  [ 5] "/home/web/app/spec/features/orders_spec.rb",
  [ 6] "/home/web/app/spec/features/sessions_spec.rb",
  [ 7] "/home/web/app/spec/lib/form_document/changes_service_spec.rb",
  [ 8] "/home/web/app/spec/lib/form_document_spec.rb",
  [ 9] "/home/web/app/spec/models/create_order_form_document_spec.rb",
  [10] "/home/web/app/spec/models/order_spec.rb",
  [11] "/home/web/app/spec/models/previous_order_form_document_spec.rb",
  [12] "/home/web/app/spec/models/update_order_form_document_spec.rb"
]

$ find /home/web/app/spec | grep _spec
/home/web/app/spec/controllers/doctors_spec.rb
/home/web/app/spec/controllers/kits_spec.rb
/home/web/app/spec/controllers/orders_spec.rb
/home/web/app/spec/controllers/sessions_spec.rb
/home/web/app/spec/features/doctors_spec.rb
/home/web/app/spec/features/orders_spec.rb
/home/web/app/spec/features/sessions_spec.rb
/home/web/app/spec/lib/form_document_spec.rb
/home/web/app/spec/lib/form_document/changes_service_spec.rb
/home/web/app/spec/models/create_order_form_document_spec.rb
/home/web/app/spec/models/order_spec.rb
/home/web/app/spec/models/previous_order_form_document_spec.rb
/home/web/app/spec/models/update_order_form_document_spec.rb

$ find /home/web/app/spec | grep _spec | wc -l
13

On the CI:

Finished in 1 minute 23.47 seconds (files took 5.61 seconds to load)
298 examples, 0 failures

On my local machine:

Finished in 15.62 seconds (files took 3.61 seconds to load)
57 examples, 0 failures

What else can I do to debug?

[JonRowe]

@gucki can you add the filter output?

[gucki]

@JonRowe What exactly? I'm not using any filters...

[JonRowe]

You've truncate the output, theres more there.

[gucki]

@JonRowe Mh, not really:

web@c22c45259372:~/app$ rspec 

Randomized with seed 24090

....

Finished in 1 minute 20.86 seconds (files took 6.88 seconds to load)
91 examples, 0 failures

Randomized with seed 24090

Coverage report generated for RSpec to /home/web/app/coverage. 1817 / 2093 LOC (86.81%) covered.
web@c22c45259372:~/app$

[2ken]

I had a similar issue today where rspec --dry-run would consistently and correctly return the same number of examples, but I would get different example count from running rspec without the flag.

The problem was that several of the examples were exiting the running process, not just throwing errors. Since --dry-run doesn’t actually run the examples, it discovers all specs without exiting the process.

I found a mistaken call to abort i.e Kernel::abort, instead of throw(:abort) in an Active Record callback for Rails. Fixing this resolved the problem.

I would try finding such possible culprits. They’d most likely be the last example listed in the output because they exit the process.

[JonRowe]

Yes using exit or abort will cause RSpec to quit because we respect Ruby semantics in that respect, wrapping an around { |ex| ex.run rescue SystemExit } etc would trap it. Although in that limited scenario I am wondering if we should print a warning about that happening...