add failing spec for issue #2299

[doits]

This is a failing spec to reproduce issue #2299.

[pirj]

I guess it boils down to:

t = Time.current
t == Time.at(t.to_f)

We do Time.at, Rails do that as well in their test helpers.

I suspect that it's ActiveJob serialization that is responsible for to_f.

Do you have an idea of how to work around that comparison issue?

[doits]

Event without .to_f it is already false:

t = Time.current
t == Time.at(t)
# => false

You could compare .to_f for simple time values, but not sure if this is the right work around:

t = Time.current
t.to_f == Time.at(t).to_f
# => true

[pirj]

At the same time:

t = Time.now
t == Time.at(t) # => true

So I guess it's something Rails-related. Do you think it's possible to work this around, would you be up to fixing this issue?

[pirj]

It's about nanosecond precision it seems and Time.at for ActiveSupport::TimeWithZone:

# Time.now isn't that precise
t = Time.now
t.nsec # => 81297000
Time.at(nsec) # => 81297000

# Neither is Time.current
t = Time.current
t.nsec # => 678132000
Time.at(t).nsec # => 678132057
Time.at(t).nsec # => 678132057
Time.at(t).nsec # => 678132057
# WAT

[doits]

Hmm for me timezone gets really weird, too:

t = Time.current

t
# => Thu, 26 Mar 2020 15:10:32 CET +01:00
Time.at(t)
# => 2020-03-26 15:10:32 3221285/4194304 +0100

Time.at(t.utc)
# => 2020-03-26 14:11:45.30499 UTC

# comparing with utc works??
t == Time.at(t.utc)
# => true

[pirj]

Nice catch!
Does changing this to Time.at(t.utc) fix the spec?

[doits]

Unfortunately not:

     Failure/Error: msg_parts << "at #{Time.at(job[:at].utc)}" if job[:at]

     NoMethodError:
       undefined method `utc' for 1585319124.371739:Float

[pirj]

Ooops, sorry for the confusion, not that Time.at, another one.

[doits]

Hehe np, I tried this too already, but same error:

     Failure/Error: values_match?(@at, Time.at(job[:at].utc))

     NoMethodError:
       undefined method `utc' for 1585319532.893687:Float

I also tried different other variations, no luck, spec fails:

            values_match?(@at.utc, Time.at(job[:at]))

            values_match?(@at.utc, Time.at(job[:at]).utc)

            values_match?(@at, Time.at(job[:at]).utc)

[pirj]

How about

values_match?(Time.at(@at), Time.at(job[:at]))

[doits]

Nope, still

     Failure/Error:
       expect {
         hello_job.set(wait_until: date).perform_later
       }.to have_enqueued_job.at(date)

       expected to enqueue exactly 1 jobs, at 2020-03-27 16:20:25.636622 +0100, but enqueued 0
       Queued jobs:
         HelloJob job on queue default, at 2020-03-27 16:20:25 +0100

I tried some more variations, all fail:

values_match?(Time.at(@at).utc, Time.at(job[:at]).utc)

values_match?(Time.at(@at.utc), Time.at(job[:at]).utc)

values_match?(Time.at(@at.utc), Time.at(job[:at]))

This one works though:

values_match?(@at.to_datetime, Time.at(job[:at]).to_datetime)

... but kills other specs, for example ...

  2) ActiveJob matchers have_enqueued_job accepts composable matchers as an at date
     Failure/Error: values_match?(@at.to_datetime, Time.at(job[:at]).to_datetime)

     NoMethodError:
       undefined method `to_datetime' for #<RSpec::Matchers::BuiltIn::BeWithin:0x00007f99971f6f70>

[JonRowe]

I feel this is an issue with job serialisation, we need to ensure we are serialising arguments the same as action job is, and then compare them.

[pirj]

I've managed to work around the rounding problem like that:

@at = Time.at(@at.to_f) if Time === @at

values_match?(@at, Time.at(job[:at]))

I believe .to_f is what happens on serialization, but I'd double check. @doits can you find any evidence if it's just that what happens to schedule time?

[JonRowe]

I mean rather than reimplementing it, we should be delegating to Rails

[doits]

Do we know why it broke with 4.0?

• Is it because now Time.at is used which wasn't before in 3.9?
• Or is it because rspec-rails serializes attributes differently than on 3.9?

Maybe it could be reverted so it will work again.

And then what is the real problem with 4.0 right now?

• Is it that t = Time.current; t == Time.at(t) is false?
  If yes, is this actually wrong on the Rails end side? I asked theme here: Time.at(time) != time rails/rails#38831
• Or is it some rounding error?

[pirj]

we should be delegating to Rails

Sorry, I probably don't quite understand what you mean. I don't see a clear way to pass our expected values to Rails for further comparison, due to argument matchers that can be used instead of the real values (e.g. regexp for a with or be_yesterday), or even block expectation for arguments:

have_enqueued_job(hello_job).with { |arg|
  expect(arg).to eq("zxcv")
}

[pirj]

Rails is rounding expected at value in assert_enqueued_with:

      def prepare_args_for_assertion(args)
        args.dup.tap do |arguments|
          arguments[:at] = round_time_arguments(arguments[:at]) if arguments[:at]

      def round_time_arguments(argument)
        case argument
        when Time, ActiveSupport::TimeWithZone, DateTime
          argument.change(usec: 0)

This is something we should reuse or mimic. This rounds it to the whole seconds though:

t.change(usec: 0).nsec # => 0

They also do that for the other side of the equation:

      def deserialize_args_for_assertion(job)
        job.dup.tap do |new_job|
          new_job[:at] = round_time_arguments(Time.at(new_job[:at])) if new_job[:at]

We probably don't need that.

[JonRowe]

Do we know why it broke with 4.0?

We changed the matchers significantly in 4.0 for various enhancements and bug fixes. I haven't had time to bisect it but you could with this spec.

Maybe it could be reverted so it will work again.

I'm going to say no because of the scope of the changes but you could just use 3.9 if that worked for you until its fixed? Or help fix it for a 4.0.1!

Sorry, I probably don't quite understand what you mean.

@pirj Jobs are serialised, we should serialise/deserialise arguments where appropriate.

[benoittgt]

I git bisect and found a commit: b1e27e2

It was related to #2205

---

The repo I used with the spec file: https://github.com/benoittgt/testing_6_0_0_rc1/blob/active-job-time-error/spec/jobs/guests_cleanup_job_spec.rb

require 'rails_helper'

RSpec.describe GuestsCleanupJob, type: :job do
  before do
    ActiveJob::Base.queue_adapter = :test
  end

  it 'enque the job' do
    date = Time.current.utc.change(usec: 0) + 1.day
    expect {
      GuestsCleanupJob.set(wait_until: date).perform_later
    }.to have_enqueued_job.at(date)
  end

  it 'enque the job without usec change' do
    date = Time.current.utc + 1.day
    expect {
      GuestsCleanupJob.set(wait_until: date).perform_later
    }.to have_enqueued_job.at(date)
  end
end

The first spec is always green. Even on 3.9.1. The second spec, failed after b1e27e2 was introduced. :)

[doits]

Do we know why it broke with 4.0?

We changed the matchers significantly in 4.0 for various enhancements and bug fixes. I haven't had time to bisect it but you could with this spec.

@benoittgt found the commit, good job 👍.

By a quick look Time.at was introduced there and comparing with .to_f was removed, so maybe this is the culprit, indeed? If yes, there is no other way to work around it in rspec-rails even if Rails might fix rails/rails#38831 since it would only work with newer Rails versions then. Though it is not clear yet if this is actually a Rails' Time.at bug or not, they didn't answer yet.

Maybe it could be reverted so it will work again.

I'm going to say no because of the scope of the changes but you could just use 3.9 if that worked for you until its fixed? Or help fix it for a 4.0.1!

Yeah, I'm using 3.9 and I started an issue here with a MR to help to find a fix, so I'm on it ;-). Reverting would be just a quick fix until the real cause is found. Since there is no other issue opened yet, it looks like I am the only one with this problem, so maybe it is not so important to revert it until a real solution is found which can take some time.

Jobs are serialised, we should serialise/deserialise arguments where appropriate.

The question for me is: Why is job[:at] a float? I'm not so familiar with Rails internals, but it looks like .to_f is simply hardcoded.

serialize_and_deserialize_arguments does not convert a time to a float - maybe because it is no argument?

So maybe calling .to_f (#2301 (comment)) is a special treatment necessary only for this case in case @at is no rspec matcher?

Edit: It could be implemented in #at, too, if this fits better.

          def at(date)
            @at = Time === date ? Time.at(date.to_f) : date
            self
          end

It fixes the spec, too.

[syakovyn]

A quick question: why just not to change
values_match?(@at, Time.at(job[:at])) to values_match?(@at.to_f, job[:at]) in RSpec::Rails::Matchers::ActiveJob::Base#at_match??

In that way, it kinda returns to what we have in 3.9.

Or if it doesn't work for some reason use values_match?(@at.to_f, Time.at(job[:at]).to_f)

I solved my issue by wrapping at expectation into Time.at, thus, converting the comparison intovalues_match?(Time.at(@at), Time.at(job[:at]))

[pirj]

Good job bisecting, I had a strong suspicion it was my change that led to this behavior change. 🤦‍♂

Let's dissect the problem into two by following how Rails does it.

1. Mimic how Rails approaches the problem in prepare_args_for_assertion and round @at (if it's === Time) and also job[:at] (to follow deserialize_args_for_assertion to whole seconds before comparing them.

2. Reuse Rails test code that does that (by including ActiveJob::TestHelper). I have little to no idea why would round_time_arguments recurse over nested hashes and arrays to round all Time descendants to whole seconds, I'm more inclined to keep off of following this.

I still disagree that we have to pass our expected values through AJ's serialization before comparing them to AJ, we'll have to keep track of which arguments were regular values and which were matchers, only pass regular values. I imagine this as more code than the approach above.

There could be potential failures in existing specs, with any taken approach that involves rounding e.g.:

now = Time.now
expect {
  SomeJob.set(wait_until: now).perform_later
}.to enqueue_job.at(be_within(0.2.seconds).from(now))

The above will round @at from 0.6 to 1.0, and job[:at], which will be 0.7 and will be rounded to 1.0 won't fit into +-0.2s (0.4..0.8) anymore.

Yet another possible solution I personally favour is to fix Time.at for ActiveSupport::TimeWithZone. If it's released in, say, Rails 6.0.3, odds are that most people will update to it soon, and we won't have this problem anymore as well by getting rid of the root cause.

[pirj]

We have a solution on how to get the problem of Time.at out of the equation (by putting it to both sides of the equation):

            @at = Time.at(@at.to_f) if Time === @at

            values_match?(@at, Time.at(job[:at]))

We obviously don't follow how Rails does it in their matchers, but neither we did that before, our AJ/AM matchers are all written from scratch.

Obviously, the same problem might pop up for the arguments, e.g.:

SomeJob.perform_later([1.day.ago, 2.days.ago])

but tackling it would be working around serialization/deserialization bugs that we're not responsible for.

[pirj]

A quick question: why just not to change values_match?(@at, Time.at(job[:at])) to values_match?(@at.to_f, job[:at]) in RSpec::Rails::Matchers::ActiveJob::Base#at_match?

@syakovyn @at can be a Time or an argument matcher, e.g. be_within(10.seconds).of(Time.now).

[JonRowe]

Closed by #2304