RSpec mocks 3.12 breaks test suites due to kwargs in incomprehensible manner

[voxik]

Subject of the issue

I have just sent several PR to fix test suites of Guard projects:

guard/guard#986
guard/guard-livereload#194

What is problematic is that RSpec breaks the test suite in incomprehensible way. E.g. the guard test suite failed like this:

$ rspec -rspec_helper spec
Run options: include {:focus=>true}
All examples were filtered out; ignoring {:focus=>true}
Randomized with seed 55878
..................................................................*....stub me: ENV[COLUMNS]!
Pending: (Failures listed here are expected and do not affect your suite's status)
  1) Guard::Internals::Scope#titles 
     # Not yet implemented
     # ./spec/lib/guard/internals/scope_spec.rb:93
Finished in 1.46 seconds (files took 0.68148 seconds to load)
72 examples, 0 failures, 1 pending
Randomized with seed 55878

which does not even look like failure, except the return code. Please note that there is not COLUMNS string in the whole guard code base.

The guard-livereload was failing in following way:

$ rspec spec
Run options: include {:focus=>false}
All examples were filtered out; ignoring {:focus=>false}
Randomized with seed 58149

... snip ...

FF....................
Failures:
  1) Guard::LiveReload#start creates reactor with given options
     Failure/Error: @reactor = Reactor.new(options)
     RuntimeError:
       CRITICAL: RUBYGEMS_ACTIVATION_MONITOR.owned?: before false -> after true
     # ./lib/guard/livereload.rb:32:in `start'
     # ./spec/lib/guard/livereload_spec.rb:144:in `block (3 levels) in <top (required)>'
     # ------------------
     # --- Caused by: ---
     # RuntimeError:
     #   stub called for File.expand_path("/usr/share/gems/gems/http_parser.rb-0.6.0/lib/pp")
     #   ./spec/lib/guard/livereload_spec.rb:12:in `block (3 levels) in <top (required)>'
  2) Guard::LiveReload#start creates reactor with default options
     Failure/Error: fail "stub called for File.expand_path(#{args.map(&:inspect) * ','})"
     RuntimeError:
       stub called for File.expand_path("/usr/share/gems/gems/http_parser.rb-0.6.0/lib/pp")
     # ./spec/lib/guard/livereload_spec.rb:12:in `block (3 levels) in <top (required)>'
     # ./lib/guard/livereload.rb:32:in `start'
     # ./spec/lib/guard/livereload_spec.rb:130:in `block (3 levels) in <top (required)>'
Finished in 0.08103 seconds (files took 0.20378 seconds to load)
35 examples, 2 failures

This is frustrating, because if you check the fixes, they really fix the kwargs. One might say that Guard is using some unorthodox ways of stubbing some calls. But OTOH, it is not nice that it really is not obvious what is going on. And surprisingly, in both cases the error is related to loading/using pp.

I don't know if there is anything actionable here. Maybe the pp could be preloaded or it would not need to be used at all. Maybe there is a way to release changes like this when they are more polished. Maybe you can distill some bits of this report into separate tickets. I leave it to your consideration and will not be super sad if you just nod and close the ticket :)

[JonRowe]

I'm very confused by those messages, they are not at all what I would expect from an rspec-mocks failure, if you check the source of these changes you'll see you should actually get a diff of args with keyword or hash added to the output to differentiate between them... and indeed running guard master locally I get proper failures:

1) Guard::Commands::Scope with a valid Guard group scope sets up the scope with the given scope
     Failure/Error: session.interactor_scopes = scopes

       #<Guard::Internals::Session:21520> received :interactor_scopes= with unexpected arguments
         expected: ({:groups=>[:frontend], :plugins=>[]}) (keyword arguments)
              got: ({:groups=>[:frontend], :plugins=>[]}) (options hash)
       Diff:

     # ./lib/guard/commands/scope.rb:36:in `process'
     # ./spec/lib/guard/commands/scope_spec.rb:34:in `block (3 levels) in <top (required)>'

  2) Guard::Commands::Scope with a valid Guard plugin scope runs the :scope= action with the given scope
     Failure/Error: session.interactor_scopes = scopes

       #<Guard::Internals::Session:21660> received :interactor_scopes= with unexpected arguments
         expected: ({:groups=>[], :plugins=>[:dummy]}) (keyword arguments)
              got: ({:groups=>[], :plugins=>[:dummy]}) (options hash)
       Diff:

     # ./lib/guard/commands/scope.rb:36:in `process'
     # ./spec/lib/guard/commands/scope_spec.rb:43:in `block (3 levels) in <top (required)>'

  3) Guard::Interactor#options & #options= options set after interactor is instantiated set the options and initialize a new interactor job
     Failure/Error: @_idle_job ||= _job_klass.new(engine, options)

       #<Guard::Jobs::PryWrapper (class)> received :new with unexpected arguments
         expected: (#<Guard::Engine:22260 @options={:watchdirs=>"/Users/jon/Code/Scratch/guard", :inline=>"guard :dummy", :no_interactions=>true}>, {:foo=>:bar}) (keyword arguments)
              got: (#<Guard::Engine:22260 @options={:watchdirs=>"/Users/jon/Code/Scratch/guard", :inline=>"guard :dummy", :no_interactions=>true}>, {:foo=>:bar}) (options hash)
       Diff:

     # ./lib/guard/interactor.rb:60:in `_idle_job'
     # ./spec/lib/guard/interactor_spec.rb:57:in `block (4 levels) in <top (required)>'

  4) Guard::Engine#start listener initialization initializes the listener
     Failure/Error:
       expect(Listen).to receive(:to)
         .with("/foo", latency: 2, wait_for_delay: 1).and_return(listener)

       Listen received :to with unexpected arguments
         expected: ("/foo", {:latency=>2, :wait_for_delay=>1}) (keyword arguments)
              got: ("/foo", {:latency=>2, :wait_for_delay=>1}) (options hash)
       Diff:

     # ./spec/lib/guard/engine_spec.rb:41:in `block (4 levels) in <top (required)>'

  5) Guard::Notifier.notify with multiple parameters notifies
     Failure/Error:
       expect(notifier).to receive(:notify)
         .with("A", priority: 2, image: :failed)

       #<InstanceDouble(Notiffany::Notifier) (anonymous)> received :notify with unexpected arguments
         expected: ("A", {:image=>:failed, :priority=>2}) (keyword arguments)
              got: ("A", {:image=>:failed, :priority=>2}) (options hash)
       Diff:

     # ./spec/lib/guard/notifier_spec.rb:64:in `block (4 levels) in <top (required)>'

Finished in 4.26 seconds (files took 0.25036 seconds to load)
523 examples, 5 failures

We do use pp to pretty print objects to diff them, and we delay loading it until its needed to avoid someoverheads (if you never fail you never load pp) but it feels like prehaps this issue doesn't lie within RSpec, but in something guard is doing?

[cfurrow]

I'm having similar issue, but not on 3.12. It was when I was updating to rspec-mocks 3.11.2 from 3.11.1

ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [x86_64-darwin21]
macOS Ventura 13.0
rspec-core 3.11.0
rspec-expectations 3.11.1
rspec-rails 6.0.1 (this is what caused the bump to rspec-mocks 3.11.1 to 3.11.2 in my case, I was on 6.0.0)

Example of failing expectation:

expect(described_class.tracker).to receive(:track).with(
    user_id: user.id,
    event: event,
    properties: properties.merge(common_event_properties),
    timestamp: timestamp,
    anonymous_id: nil
  )

Failure output:

  RSpec::Mocks::MockExpectationError #<...snip...>
  Failure/Error: tracker.track(payload)
  
    #<Client:0x00007fe9bd2adc90 @config=#<...snip...>> received :track with unexpected arguments
      expected: ({ user_id: 612, event: "non", properties: { fake_property: "fake value", has_primary: true, track_id: 131, track_assignment_id: 129, product_id: nil, product_subscription_id: nil, product_subscription_assignment_id: nil, deployment_type: "standard", hubspot_contact_id: nil }, timestamp: #<DateTime 2020-01-01 00:00:00 +00:00 (+00:00)>, anonymous_id: nil, integrations: ["Amplitude"] })
           got: ({ user_id: 612, anonymous_id: nil, event: "non", properties: { fake_property: "fake value", has_primary: true, track_id: 131, track_assignment_id: 129, product_id: nil, product_subscription_id: nil, product_subscription_assignment_id: nil, deployment_type: "standard", hubspot_contact_id: nil }, timestamp: #<DateTime 2020-01-01 00:00:00 +00:00 (+00:00)>, integrations: ["Amplitude"] })

When trying to debug the above, I switched to the .receive(...) block syntax, but that seemed to fix it with no additional changes to the failing spec or underlying code:

expect(described_class.tracker).to receive(:track) do |args|
  expected_args = {
    user_id: user.id,
    event: event,
    properties: properties.merge(common_event_properties),
    timestamp: timestamp,
    anonymous_id: nil
  }
  # I used .eq() and .match() and both seem to work and pass.
  expect(args).to match(expected_args)
end

[pirj]

Would you please update to rspec-mocks 3.12.0, @cfurrow to see some additional information introduced here?

It would be helpful to see how you pass arguments to .track in your code under test.

[cfurrow]

Ok, updated rspec-mocks to 3.12.0 (had to bump rspec, rspec-core, rspec-expectations, etc, to 3.12.0 first)

The syntax to call this .track method when under test is nothing special. Here's an example of one of the spec examples I updated to use .receive(...) do; end. Note that described_class.track is a convenience method that delegates to described_class.tracker.track:

# NOTE: this example passes when I converted it to the block-form of .receive(...) from .receive(...).with(...)
it do
  expect(described_class.tracker).to receive(:track) do |args|
    expected_args = {
      user_id: user.id,
      event: event,
      properties: properties.merge(common_event_properties),
      timestamp: timestamp,
      anonymous_id: nil
    }

    expect(args).to match(expected_args)
  end

  described_class.track(user: user, event: event, properties: properties, timestamp: timestamp)
end

I have not converted all of my examples in this file to use the block form of .receive(...), so some spec examples still fail with the original error message I saw under rspec-mocks 3.11.2.

This failure is for this example:

it do
  expect(described_class.tracker).to receive(:track).with(
    user_id: user.id,
    event: event,
    properties: properties.merge(common_event_properties),
    timestamp: timestamp,
    anonymous_id: nil
  )

  described_class.track(user: user, event: event, properties: properties, timestamp: timestamp)
end

 1) AnalyticsService.track when ...snip
     Failure/Error: tracker.track(payload)

       #<Client:...snip...> received :track with unexpected arguments
         expected: ({ user_id: 16, event: "voluptatem", properties: { fake_property: "fake value", has_primary: true, track_id: 4, track_assignment_id: 4, product_id: nil, product_subscription_id: nil, product_subscription_assignment_id: nil, deployment_type: "standard", hubspot_contact_id: nil, app_version: nil, app_build: nil, platform_name: "Android", platform_version: nil, browser_name: "okhttp", browser_version: "1.23.4" }, timestamp: #<DateTime 2020-01-01 00:00:00 +00:00 (+00:00)>, anonymous_id: nil })
              got: ({ user_id: 16, anonymous_id: nil, event: "voluptatem", properties: { fake_property: "fake value", has_primary: true, track_id: 4, track_assignment_id: 4, product_id: nil, product_subscription_id: nil, product_subscription_assignment_id: nil, deployment_type: "standard", hubspot_contact_id: nil, app_version: nil, app_build: nil, platform_name: "Android", platform_version: nil, browser_name: "okhttp", browser_version: "1.23.4" }, timestamp: #<DateTime 2020-01-01 00:00:00 +00:00 (+00:00)> })
       Diff:

     # ./app/services/analytics_service.rb:67:in `track'
     # ./spec/services/analytics_service_spec.rb:1740:in `block (5 levels) in <main>'

That does not seem like a different error under rspec + rspec-mocks 3.12.0, which makes me think it was introduced as part of rspec-mocks 3.11.2.

[pirj]

An obvious difference is properties: properties.merge(common_event_properties) vs properties: properties. Can it cause the failure?

[cfurrow]

Nope, same failure when changing the call to .track to use properties.merge(...)

it do
  expect(described_class.tracker).to receive(:track).with(
    user_id: user.id,
    event: event,
    properties: properties.merge(common_event_properties),
    timestamp: timestamp,
    anonymous_id: nil
  )

  described_class.track(user: user, event: event, properties: properties.merge(common_event_properties), timestamp: timestamp)
end

1) AnalyticsService.track when ...snip...
     Failure/Error: tracker.track(payload)

       #<Client:0x00007ff0d8022940 ...snip...> received :track with unexpected arguments
         expected: ({ user_id: 20, event: "commodi", properties: { fake_property: "fake value", has_primary: true, track_id: 5, track_assignment_id: 5, product_id: nil, product_subscription_id: nil, product_subscription_assignment_id: nil, deployment_type: "standard", hubspot_contact_id: nil, app_version: nil, app_build: nil, platform_name: "Android", platform_version: nil, browser_name: "okhttp", browser_version: "1.23.4" }, timestamp: #<DateTime 2020-01-01 00:00:00 +00:00 (+00:00)>, anonymous_id: nil })
              got: ({ user_id: 20, anonymous_id: nil, event: "commodi", properties: { fake_property: "fake value", has_primary: true, track_id: 5, track_assignment_id: 5, product_id: nil, product_subscription_id: nil, product_subscription_assignment_id: nil, deployment_type: "standard", hubspot_contact_id: nil, app_version: nil, app_build: nil, platform_name: "Android", platform_version: nil, browser_name: "okhttp", browser_version: "1.23.4" }, timestamp: #<DateTime 2020-01-01 00:00:00 +00:00 (+00:00)> })
       Diff:

     # ./app/services/analytics_service.rb:67:in `track'
     # ./spec/services/analytics_service_spec.rb:1740:in `block (5 levels) in <main>'

Update Converting this failing spec example to the block-form of .receive(...) seems to "fix" the failure, similar to the previous failures and fixes I've done.

it do
  expect(described_class.tracker).to receive(:track) do |args|
    expected_args = {
      user_id: user.id,
      event: event,
      properties: properties.merge(common_event_properties),
      timestamp: timestamp,
      anonymous_id: nil
    }

    expect(args).to match(expected_args)
  end

  described_class.track(user: user, event: event, properties: properties.merge(common_event_properties), timestamp: timestamp)
end

[cfurrow]

By the way, @pirj, I appreciate your quick replies here. I was simply commenting initially help build a context of the possible bug that the original poster was seeing. I was hoping it may be enough to realize what recent change may have caused this. Thanks for sticking with it.

[pirj]

I'd rather take the merge part out, as this adds some volatility.
And would incrementally reduce the list of keys starting with properties, then timestamp to narrow it down to what is causing the failure.

I understand that the block form doesn't have this failure, but it doesn't help much to track the problem.

My initial assumption was that on the code you pass it in as a hash, but pass kwargs to .with, but it doesn't seem to be the case, 3.12.0 would detect and report this.

[cfurrow]

Changes to rspec-mocks from 3.11.2 -> 3.12.0 that seem related, but I've not completely understood them yet:

lib/rspec/mocks/argument_list_matcher.rb: v3.11.1...v3.12.0#diff-ae171e2be1f799a6704fcbadb353721dda4d078185aa265671e07b14594c72e5L49-R74

lib/rspec/mocks/error_generator.rb: v3.11.1...v3.12.0#diff-5b28aeeb36e96d3d3567364a3c0dff29001eae3a81bce2752e29b9d3bca04fbeR271-R281

lib/rspec/mocks/matchers/receive.rb: v3.11.1...v3.12.0#diff-8efd45e556df39ba1efa67c1086d56aba98e46a6a4fb31e9d9246505caf4451cL65-R65

lib/rspec/mocks/message_expectation.rb: v3.11.1...v3.12.0#diff-afc11368b62c27a5bd155b766ec9cf4e96a9331d073b6123a9bce36a270de640L142-R810

lib/rspec/mocks/method_double.rb: v3.11.1...v3.12.0#diff-df0ec6501cb8ef91a9806b4a90bb265b7d4affbbf4994bde7033f02b9ca92827R66-R82

lib/rspec/mocks/method_reference.rb: v3.11.1...v3.12.0#diff-68b5edb44e7a864abc3329011e7186acd8ec5895890682dda8e6f986af1584dcL188-R204

There may be more.

[pirj]

@voxik
This change is reasonable:

- expect(Guard::LiveReload::Reactor).to receive(:new).with(
+ expect(Guard::LiveReload::Reactor).to receive(:new).with({

As options is a regular Hash, and you pass it to Reactor.new. On Ruby 3+, there is a difference.

rspec-mocks 3.12.0 is supposed to point at this kind of failures, marking expected and actual with their internal type ("(keyword arguments)" vs "(options hash)").

[pirj]

The same seem to be the case for your other PR:

- .with(groups: [:frontend], plugins: [])
+ .with({ groups: [:frontend], plugins: [] })

Call

session.interactor_scopes = scopes

and scopes initialization:

scopes, = session.convert_scopes([])

If e.g. Reactor.initialize or Session#interactor_scope= would really have kwargs in their method signature, on Ruby 3+ you would get an error message:

ArgumentError: wrong number of arguments (given 1, expected 0; required keyword: ...)

I might be mistaken, but an option is to pass them there as such:

Reactor.new(**options)

but that won't work with attr_accessor :interactor_scopes like session.interactor_scopes=(**scopes).

If this is the culprit, I'm uncertain if we should check if the stub's method signature has kwargs, and if it doesn't, skip checking for hash vs kwargs difference on Ruby 3+.

[pirj]

@cfurrow It's hard to say that there is anything wrong with rspec-mocks here to start bisecting it.
I'd rather narrow down your use case to have a minimal reproduction example. Can you help out with this?

[cfurrow]

This repo demonstrates the failure exactly: https://github.com/cfurrow/rspec-mocks-fail-example

bin/rspec

AnalyticsService
  .track
    does not fail when I use .receive().with() (FAILED - 1)
    does not fail when I use .receive() block-form

Failures:

  1) AnalyticsService.track does not fail when I use .receive().with()
     Failure/Error: tracker.track(payload)

       #<Tracker:0x0000000107ddf510> received :track with unexpected arguments
         expected: ({:anonymous_id=>nil, :event=>"foobar", :properties=>{:deployment_type=>"standard", :fake_property=>"f...9}, :timestamp=>#<DateTime: 2020-01-01T00:00:00+00:00 ((2458850j,0s,0n),+0s,2299161j)>, :user_id=>1}) (keyword arguments)
              got: ({:anonymous_id=>nil, :event=>"foobar", :properties=>{:deployment_type=>"standard", :fake_property=>"f...9}, :timestamp=>#<DateTime: 2020-01-01T00:00:00+00:00 ((2458850j,0s,0n),+0s,2299161j)>, :user_id=>1}) (options hash)
       Diff:

     # ./lib/analytics_service.rb:26:in `track'
     # ./spec/lib/analytics_service_spec.rb:31:in `block (3 levels) in <top (required)>'

Finished in 0.03275 seconds (files took 0.15496 seconds to load)
2 examples, 1 failure

Failed examples:

rspec ./spec/lib/analytics_service_spec.rb:23 # AnalyticsService.track does not fail when I use .receive().with()

[cfurrow]

I'm trying to setup a branch on https://github.com/cfurrow/rspec-mocks-fail-example that changes rspec-mocks back to v3.11.1, but doing so has not given me the same failure I saw in my main repo. It fails the same way that rspec-mocks 3.12.0 is failing.

https://github.com/cfurrow/rspec-mocks-fail-example/compare/rspec-mocks-3.11.1?expand=1

I still only get one passing and one failing spec example, like I do in v3.12.0. Hmm.

[cfurrow]

Surrounding the args in {}, seems to fix it, which makes me think it's a kwargs vs hash issue. But this was not coming up in our repo prior to the change to rspec, rspec-mocks, etc, today (we were on 3.11.0 or 3.11.1 for all related rspec gems).

Puzzling.

    it 'does not fail when I use .receive().with()' do
-      expect(described_class.tracker).to receive(:track).with(
+      expect(described_class.tracker).to receive(:track).with({
           user_id: user.id,
           event: event,
           properties: properties.merge(common_event_properties),
           timestamp: timestamp,
           anonymous_id: nil
-        )
+        })

Our CI environment is still setup with rspec 3.11.0, rspec-mocks 3.11.1, rspec-expectations 3.11.1, etc, and is not showing failures for the specs I've shown in this issue.