ActiveJob Matcher .at() fails with comparison of ActiveSupport::TimeWithZone and Time

[hughkelsey]

What Ruby, Rails and RSpec versions are you using?

Ruby version: ruby 2.6.3p62
Rails version: Rails 6.0.2.2
RSpec version: RSpec 3.9

• rspec-core 3.9.2
• rspec-expectations 3.9.2
• rspec-mocks 3.9.1
• rspec-rails 4.0.0
• rspec-support 3.9.3

Observed behaviour

I'm using timecop to freeze time and run a job that is delayed 5 seconds.

Failures:

  1) SayHiJob should send in 5 seconds
     Failure/Error: expect { SayHiJob.perform_in_five }.to have_enqueued_job(SayHiJob).at(time + 5)

       expected to enqueue exactly 1 jobs, at Wed, 13 May 2020 13:25:42 UTC +00:00, but enqueued 0
       Queued jobs:
         SayHiJob job with [[]], on queue default, at 2020-05-13 06:25:42 -0700
     # ./spec/jobs/say_hi_job_spec.rb:8:in `block (3 levels) in <top (required)>'
     # /Users/hkelsey/.rvm/gems/ruby-2.6.3/gems/timecop-0.9.1/lib/timecop/timecop.rb:201:in `travel'
     # /Users/hkelsey/.rvm/gems/ruby-2.6.3/gems/timecop-0.9.1/lib/timecop/timecop.rb:129:in `send_travel'
     # /Users/hkelsey/.rvm/gems/ruby-2.6.3/gems/timecop-0.9.1/lib/timecop/timecop.rb:51:in `freeze'
     # ./spec/jobs/say_hi_job_spec.rb:7:in `block (2 levels) in <top (required)>'

Finished in 0.0321 seconds (files took 0.87185 seconds to load)

Expected behaviour

The spec should pass as these are the same times.

This failure happened after upgrading from 4.0.0.beta3 and is likely related to this commit:
f345e82

[26] pry(main)> time = Time.current
=> Wed, 13 May 2020 13:40:46 UTC +00:00
[27] pry(main)> Time.at(time.to_f)
=> 2020-05-13 06:40:46 -0700
[28] pry(main)> time == Time.at(time.to_f)
=> false

Can you provide an example app?

https://github.com/hughkelsey/ActiveJobMatcherAt

The relevant code is:

class SayHiJob < ApplicationJob
  queue_as :default

  def perform(*args)
    # Do something later
  end

  def self.perform_in_five(*args)
    set(wait: 5).perform_later(args)
  end
end

require 'rails_helper'

RSpec.describe SayHiJob, type: :job do
  let(:time) { Time.current }
  it 'should send in 5 seconds' do
    ActiveJob::Base.queue_adapter = :test
    Timecop.freeze time do
      expect { SayHiJob.perform_in_five }.to have_enqueued_job(SayHiJob).at(time + 5)
    end
  end
end

[JonRowe]

👋 This is likely a precision issue:

 :001 > time = Time.current
 => Thu, 14 May 2020 11:12:12 UTC +00:00
 :002 > time_to_f = Time.at(time.to_f)
 => 2020-05-14 12:12:12 +0100
 :003 > time == time_to_f
 => false
 :004 > time.nsec
 => 979171000
 :005 > time_to_f.nsec
 => 979171037

So the times are not identical, it should be nothing to do with timezone, was your original test introduced in an earlier 4.0.0 beta? As the change you reference was actually a bug fix restoring this rounding behaviour which is the same as what is supposed to happen in rails internally.

[pirj]

There's a lengthy discussion about time precision, jobs, testing, Rails' excessive trust for Ruby stability, lack of Ruby core specs etc here rails/rails#38831

Wondering if you would consider replacing Timecop.freeze with a more flexible expectation:

it 'is scheduled in 5 seconds' do
  expect { SayHiJob.perform_in_five }
    .to have_enqueued_job(SayHiJob).at(a_value_within(5.seconds).of(Time.current))
end

[benoittgt]

Hello @hughkelsey

This is an old trick. But in your repo.

--- a/spec/jobs/say_hi_job_spec.rb
+++ b/spec/jobs/say_hi_job_spec.rb
@@ -1,7 +1,7 @@
 require 'rails_helper'

 RSpec.describe SayHiJob, type: :job do
-  let(:time) { Time.current }
+  let(:time) { Time.current.change(nsec: 0) }

And it's green.

I think the issue could be closed.

[hughkelsey]

Thanks everyone for the comments and suggestions, they all work. These specs have been green for a long time and the change between 4.0.0.beta3 and 4.0.0 caused me to open the issue.

[JonRowe]

Having played with this some more to add a regression check, theres something funny going on with your time, using freeze_time { } from Rails I can't make it fail at all, (despite the fact that Time.current is accessed after the job is enqueued)... I think TimeCop may be messing with the precision? Can you try swapping it for freeze_time { .. }?

[JonRowe]

I've dug into this some more and this is a genuine precision error in the input value.

The core issue here is that Rails, allows microsecond (usec) precision in job queue values, and uses .to_f for exact time scheduling, which we replicated in #2157, without this to_f you cannot check exact time scheduled jobs.

However when Rails schedules a job in the future using wait: n it is doing n.seconds.from_now which does not get passed through to_f, there is no way for us to detect which is correct so we'll stick with out existing handling, but warn about this precision issue, adding change(usec: 0) or using (in your case):

Timecop.freeze time do
  expect { SayHiJob.perform_in_five }.to have_enqueued_job(SayHiJob).at(5.seconds.from_now)
end

Will work, and we are looking at adding a warning when we detect this scenario is possible.

[maruarcus]

travel_to and travel_back did the trick for me