Use more display precision for Time and DateTime #416

Merged
merged 1 commit into from Jan 11, 2014

Projects

None yet

3 participants

@thomas-holmes
Member

Use more display precision for Time and DateTime

The eq matcher often results in confusing output when comparing Time
and DateTime objects.

Time#inspect returns a value that is not full precision. This often
leads to a confusing failure message when two time objects differ by
fractional seconds. The matcher returns a failure but the diff shows
identical values. Microseconds have been added to the diff output for
Time.

By default DateTime#inspect outputs enough precision to prevent this
problem. ActiveSupport monkey patches #inspect to print a more human
readable but ambiguous representation. If ActiveSupport is defined a
custom format string is used for DateTime that has enough precision
to differentiate the two objects.

Fixes rspec/rspec-expectations#331

@thomas-holmes
Member

This PR isn't ready yet, explanation to follow.

For the Time class I've just put the microseconds on the end.

For both or either of these I can of course work up more complex format strings but I wanted to try to keep things as possible for the first pass

With the current state of this PR time output looks like this:

 Failure/Error: expect(messages[1]).to eq(messages[2])

   expected: "1969-12-31 19:01:40 -0500 101μs)"
        got: "1969-12-31 19:01:40 -0500 102μs)"

   (compared using ==)

I'm thinking I should probably rewrite the format string to put microseconds on the end of seconds so that it looks like:

 Failure/Error: expect(messages[1]).to eq(messages[2])

   expected: "1969-12-31 19:01:40.000101 -0500)"
        got: "1969-12-31 19:01:40.000102 -0500)"

   (compared using ==)

For DateTime I wanted to try to reuse the original inspect values. Unfortunately it's default formatting logic is more complex. ActiveSupport tries to provide a way to access the original implementation of the inspect method but unfortunately there is a bug with the default_inspect alias. ActiveSupport sets up this alias and then aliases it again to another imprecise representation. I've opened a PR for this, see rails/rails#13628.

@thomas-holmes
Member

Went ahead and changed the format to use the format in my second suggestion. I'll squash it all together when we're ready.

@myronmarston myronmarston and 1 other commented on an outdated diff Jan 8, 2014
lib/rspec/matchers/built_in/eq.rb
end
def diffable?; true; end
+
+ private
+
+ def format_object(object)
+ case object
+ when Time then format_time(object)
+ when DateTime then format_date_time(object)
@myronmarston
myronmarston Jan 8, 2014 Member

DateTime is not defined unless you have required the date library:

➜  rspec-mocks git:(add-deprecations-for-519-to-2-99) ✗ irb
irb(main):001:0> Time
=> Time
irb(main):002:0> DateTime
NameError: uninitialized constant DateTime
    from (irb):2
    from /Users/myron/.rubies/ruby-2.0.0-p247/bin/irb:12:in `<main>'
irb(main):003:0> require 'date'
=> true
irb(main):004:0> DateTime
=> DateTime

So, I think this needs to be an if statement:

if Time === object
  format_time(object)
elsif defined?(DateTime) && DateTime === object
  format_date_time(object)
else
  object.inspect
end
@thomas-holmes
thomas-holmes Jan 8, 2014 Member

Good call, I knew you have to require date but I forgot that we might end up in this code when we don't have it required.

@myronmarston
myronmarston Jan 8, 2014 Member

You could even add a spec for this (since it was wrong initially), where you use hide_const("DateTime") in the spec -- that should fail with a const missing error as the code currently exists, and then pass once you update to check defined?(DateTime) It'll help prevent future regressions.

@myronmarston myronmarston and 1 other commented on an outdated diff Jan 8, 2014
lib/rspec/matchers/built_in/eq.rb
end
def diffable?; true; end
+
+ private
+
+ def format_object(object)
+ case object
+ when Time then format_time(object)
+ when DateTime then format_date_time(object)
+ else object.inspect end
+ end
+
+ @@time_format = "%Y-%m-%d %H:%M:%S"
@myronmarston
myronmarston Jan 8, 2014 Member

Do you mind using a constant instead of a class variable? Class vars are weird in ruby, and I think it's generally good to avoid them because of their gotchas. A constant would work just as well.

@thomas-holmes
thomas-holmes Jan 8, 2014 Member

Of course.

@myronmarston myronmarston commented on an outdated diff Jan 8, 2014
lib/rspec/matchers/built_in/eq.rb
end
def diffable?; true; end
+
+ private
+
+ def format_object(object)
+ case object
+ when Time then format_time(object)
+ when DateTime then format_date_time(object)
+ else object.inspect end
+ end
+
+ @@time_format = "%Y-%m-%d %H:%M:%S"
+ # Append microseconds to the default format string
+ def format_time(time)
+ "#{time.strftime(@@time_format)}.%06d #{time.strftime("%z")}" % time.usec
@myronmarston
myronmarston Jan 8, 2014 Member

I think you can simplify this a bit to:

time.strftime("#{TIME_FORMAT}.#{"%06d" % time.usec} %z")
@myronmarston myronmarston and 1 other commented on an outdated diff Jan 8, 2014
lib/rspec/matchers/built_in/eq.rb
+ @@time_format = "%Y-%m-%d %H:%M:%S"
+ # Append microseconds to the default format string
+ def format_time(time)
+ "#{time.strftime(@@time_format)}.%06d #{time.strftime("%z")}" % time.usec
+ end
+
+ # ActiveSupport sometimes overrides inspect. If it does it leaves behind
+ # a `default_inspect` method. We'll use this because it has the original
+ # precision of DateTime#inspect.
+ def format_date_time(date_time)
+ if date_time.respond_to?(:default_inspect)
+ date_time.default_inspect
+ else
+ date_time.inspect
+ end
+ end
@myronmarston
myronmarston Jan 8, 2014 Member

Given the activesupport bug you have a rails PR for, what is the current behavior?

@myronmarston
myronmarston Jan 8, 2014 Member

Also, do you think this should check defined?(ActiveSupport)? In another context default_inspect could be defined but it may not be what we want.

@thomas-holmes
thomas-holmes Jan 8, 2014 Member

The current behavior will not solve the problem, both lines will show something like "Tuesday, November 22 12:34:00". I figured we might want to actually hand craft a time format for DateTime but I didn't do that yet, as I wanted to present this as an option. If I researched it correctly the default inspect for DateTime does not appear to be built with a format string but instead has some logic and is implemented in C.

I also considered checking for ActiveSupport. Checking date.defined(ActiveSupport) && date.respond.to?(:default_inspect) would probably give us more precise targeting of the issue. I can't just check for ActiveSupport alone though, due to its optional nature.

@thomas-holmes
thomas-holmes Jan 10, 2014 Member

Do you think I should just work up another format string? I feel reasonably comfortable that anything named default_inspect will be what we want but I think we may still want to use a different string so that we're not relying on an unsure ActiveSupport bug fix.

@myronmarston myronmarston and 1 other commented on an outdated diff Jan 8, 2014
spec/rspec/matchers/built_in/eq_spec.rb
@@ -54,7 +54,46 @@ module Matchers
expect(["a\nb", "c\nd"]).to eq([])
}.to fail_matching("expected: []")
end
+
+ context "Time Equality" do
+ describe Time do
+ let(:time1) { Time.utc(1969, 12, 31, 19, 01, 40, 101) }
+ let(:time2) { Time.utc(1969, 12, 31, 19, 01, 40, 102) }
+
+ it 'Should have a different output string when differing by milliseconds' do
+ matcher = eq(time1).tap { |m| m.matches?(time2) }
+
+ expect(matcher.failure_message).to match("1969-12-31 19:01:40.000101")
+ expect(matcher.failure_message).to match("1969-12-31 19:01:40.000102")
@myronmarston
myronmarston Jan 8, 2014 Member

Rather than using the matcher protocol directly (e.g. via matches? and failure_message), I prefer to see the matcher used as a user would use it:

expect {
  expect(time1).to eq(time2)
}.to fail_with(/1969-12-31 19:01:40.000102.*1969-12-31 19:01:40.000101/m)

Your spec focuses more on the implementation (e.g. the protocol methods being used) rather than the behavior (e.g. how the matcher behaves when used in a matcher expression).

@myronmarston
myronmarston Jan 8, 2014 Member

Actually, the arg passed to fail_with can be cleaned up a bit using the new composable matcher support:

expect {
  expect(time1).to eq(time2)
}.to fail_with(a_string_matching("1969-12-31 19:01:40.000101").and matching("1969-12-31 19:01:40.000102"))
@thomas-holmes
thomas-holmes Jan 8, 2014 Member

You're right, I like that better.

@myronmarston myronmarston commented on an outdated diff Jan 8, 2014
spec/rspec/matchers/built_in/eq_spec.rb
@@ -54,7 +54,46 @@ module Matchers
expect(["a\nb", "c\nd"]).to eq([])
}.to fail_matching("expected: []")
end
+
+ context "Time Equality" do
+ describe Time do
@myronmarston
myronmarston Jan 8, 2014 Member

In rspec/rspec-core#1114 we are discussing changing inner describe SomeClass so that it changes described_class to refer to that class. While we don't rely on that here, the primary class you are describing is RSpec::Matchers::BuiltIn::Eq, so I think it's better to use context "with Time objects".

@myronmarston myronmarston commented on an outdated diff Jan 8, 2014
spec/rspec/matchers/built_in/eq_spec.rb
@@ -54,7 +54,46 @@ module Matchers
expect(["a\nb", "c\nd"]).to eq([])
}.to fail_matching("expected: []")
end
+
+ context "Time Equality" do
+ describe Time do
+ let(:time1) { Time.utc(1969, 12, 31, 19, 01, 40, 101) }
+ let(:time2) { Time.utc(1969, 12, 31, 19, 01, 40, 102) }
+
+ it 'Should have a different output string when differing by milliseconds' do
+ matcher = eq(time1).tap { |m| m.matches?(time2) }
+
+ expect(matcher.failure_message).to match("1969-12-31 19:01:40.000101")
+ expect(matcher.failure_message).to match("1969-12-31 19:01:40.000102")
+ end
+ end
+
+ describe DateTime do
@myronmarston
myronmarston Jan 8, 2014 Member

Same here.

@myronmarston myronmarston commented on an outdated diff Jan 8, 2014
spec/rspec/matchers/built_in/eq_spec.rb
+ expect(matcher.failure_message).to match("1969-12-31 19:01:40.000102")
+ end
+ end
+
+ describe DateTime do
+ require 'date'
+ let(:date1) { DateTime.new(2000, 1, 1, 1, 1, Rational(1, 10)) }
+ let(:date2) { DateTime.new(2000, 1, 1, 1, 1, Rational(2, 10)) }
+
+ it 'Should have diffferent output string when differing by milliseconds' do
+ matcher = eq(date1)
+ matcher.matches?(date2)
+ messages = /expected: (.+)\n.*got: (.+)$/.match(matcher.failure_message)
+
+ expect(messages[1]).to_not eq(messages[2])
+ end
@myronmarston
myronmarston Jan 8, 2014 Member

Again, it would be nice if this used the expect { }.fail_with form. You could do this:

RSpec::Matchers.define :a_string_with_differing_datetime_output do
  match do |string|
    time_strings = /expected: (.+)\n.*got: (.+)$/.match(string).captures
    time_strings.uniq.count == 2
  end
end

it 'differentiates the date time objects when their milliseconds differ' do
  expect {
    expect(date2).to eq(date1)
  }.to fail_with(a_string_with_differing_datetime_output)
end
@myronmarston myronmarston commented on an outdated diff Jan 8, 2014
spec/rspec/matchers/built_in/eq_spec.rb
+ expect(messages[1]).to_not eq(messages[2])
+ end
+
+ describe 'default_inspect exists' do
+ it 'uses default_inspect for the failure message' do
+ allow(date1).to receive(:default_inspect).and_return("inspect message 1")
+ allow(date2).to receive(:default_inspect).and_return("inspect message 2")
+
+ matcher = eq(date1).tap { |m| m.matches?(date2) }
+
+ expect(matcher.failure_message).to match("inspect message 1")
+ expect(matcher.failure_message).to match("inspect message 2")
+ end
+ end
+ end
+ end
@myronmarston
myronmarston Jan 8, 2014 Member

There are no specs for the negated case (e.g. expect(x).not_to eq(y)) -- can you add those as well?

@myronmarston
Member

@thomas-holmes -- this is looking really good. Left a few comments, but nothing major.

BTW, in your message above, you showed the output as this:

"1969-12-31 19:01:40 -0500 101μs)"

(notice the trailing )). It looks to me like it no longer includes that trailing paren in the output, but if it does, please remove it -- it shouldn't be there, right?

@thomas-holmes
Member

@myronmarston Thanks for the thorough review. I too noticed that ) after I was done working on the PR for the night but I didn't have a chance to figure out why it's there. It might be that when I was editing the format string I accidentally ended up with a ) on the wrong side of a quote.

I don't know if I'll have time to get this cleaned up tonight but I'll do so ASAP.

@JonRowe
Member
JonRowe commented Jan 8, 2014

As usual @myronmarston provides a thorough review, I have nothing to add :)

@thomas-holmes
Member

@myronmarston I've addressed most of your comments but I'm not quite done yet. I need to get the negative case testing.

@myronmarston
Member

Looks like you'll need to rebase -- another PR was merged and there's a conflict now.

@thomas-holmes
Member

@myronmarston Oops, I pushed and ran out the door :)

I've squashed this down into one commit and pushed it back up.

@thomas-holmes thomas-holmes and 1 other commented on an outdated diff Jan 10, 2014
lib/rspec/matchers/built_in/eq.rb
@@ -19,6 +19,32 @@ def description
end
def diffable?; true; end
+
+ private
+
+ def format_object(object)
+ case object
+ when Time then format_time(object)
+ when defined?(DateTime) && DateTime then format_date_time(object)
@myronmarston
myronmarston Jan 10, 2014 Member

It works because when DateTime is defined, defined?(DateTime) && DateTime evaluates to DateTime, and so in that case it's the same as when DateTime.

However, I think this will have a bug when DateTime is not defined and object is false, (e.g. expect(x).to eq false): in that case it will call format_date_time even thought it's false and not a DateTime.

I think it's better to use an explicit if statement:

return format_time(object) if Time === object
return format_date_time(object) if defined?(DateTime) && DateTime === object
object.inspect
@myronmarston
myronmarston Jan 10, 2014 Member

Actually, it's a problem with nil, not false: defined?(DateTime) && DateTime === object evaluates to nil when DateTime is not defined.

@thomas-holmes thomas-holmes commented on an outdated diff Jan 10, 2014
spec/rspec/matchers/built_in/eq_spec.rb
+ expect {
+ expect(date1).to eq(date2)
+ }.to fail_with(a_string_with_differing_output)
+ end
+
+ it 'should not raise an exception if DateTime is not defined' do
+ hide_const('DateTime')
+ expect {
+ expect(5).to eq(4)
+ }.to raise_error(RSpec::Expectations::ExpectationNotMetError)
+ end
+
+ it 'fails with identical messages' do
+ RSpec::Matchers.define :a_string_with_same_datetime_value do
+ match do |string|
+ time_strings = /expected: value != (.+)\n.*got: (.+)$/.match(string).captures
@thomas-holmes
thomas-holmes Jan 10, 2014 Member

Negated has message with a slightly different format. I'm going to see if I can whip up regex to fit both use cases.

@thomas-holmes thomas-holmes and 1 other commented on an outdated diff Jan 10, 2014
spec/support/matchers.rb
@@ -4,6 +4,13 @@
end
end
+RSpec::Matchers.define :a_string_with_differing_output do
@thomas-holmes
thomas-holmes Jan 10, 2014 Member

Do you think I should put this in eq_spec.rb instead of here? This isn't a truly general purpose matcher for the case of the tests, but it does work for the tests I added.

@myronmarston
myronmarston Jan 10, 2014 Member

Yes, I don't think it belongs here since the regex is not general enough to work for all matchers. Put it in eq_spec.rb, please.

@myronmarston myronmarston and 1 other commented on an outdated diff Jan 10, 2014
spec/rspec/matchers/built_in/eq_spec.rb
+ end
+
+ it 'should not raise an exception if DateTime is not defined' do
+ hide_const('DateTime')
+ expect {
+ expect(5).to eq(4)
+ }.to raise_error(RSpec::Expectations::ExpectationNotMetError)
+ end
+
+ it 'fails with identical messages' do
+ RSpec::Matchers.define :a_string_with_same_datetime_value do
+ match do |string|
+ time_strings = /expected: value != (.+)\n.*got: (.+)$/.match(string).captures
+ time_strings.uniq.count == 1
+ end
+ end
@myronmarston
myronmarston Jan 10, 2014 Member

While you can define a matcher in-line in the example like this, I recommend putting it in the example group (e.g. in a describe or context block). As this exists now, someone could write another example that uses this matcher and that would pass if it ran after this one but fail if it ran before. I like to avoid ordering dependencies so putting it in the example group describe or context block defines it when the file is loaded and removes the ordering from the equation.

@thomas-holmes
thomas-holmes Jan 10, 2014 Member

Makes sense. I wasn't really sure where to put them at the time. To the example group with them!

@thomas-holmes thomas-holmes commented on the diff Jan 11, 2014
lib/rspec/matchers/built_in/eq.rb
+ if Time === object
+ format_time(object)
+ elsif defined?(DateTime) && DateTime === object
+ format_date_time(object)
+ else
+ object.inspect
+ end
+ end
+
+ TIME_FORMAT = "%Y-%m-%d %H:%M:%S"
+ # Append microseconds to the default format string
+ def format_time(time)
+ time.strftime("#{TIME_FORMAT}.#{"%06d" % time.usec} %z")
+ end
+
+ DATE_TIME_FORMAT = "%a, %d %b %Y %H:%M:%S.%6N %z"
@thomas-holmes
thomas-holmes Jan 11, 2014 Member

This looks like the following:

 Failure/Error: expect(date1).to eq(date2)

   expected: Sat, 01 Jan 2000 01:01:00.200000 +0000
        got: Sat, 01 Jan 2000 01:01:00.100000 +0000

   (compared using ==)
@myronmarston
myronmarston Jan 11, 2014 Member

👍 That looks great.

Seeing your time format string makes me think that you might be able to simplify the TIME_FORMAT string even further so that there's not the separate % time.usec bit. Would %6N work in that as well?

@thomas-holmes thomas-holmes Use more display precision for Time and DateTime
The `eq` matcher often results in confusing output when comparing `Time`
and `DateTime` objects.

`Time#inspect` returns a value that is not full precision. This often
leads to a confusing failure message when two time objects differ by
fractional seconds. The matcher returns a failure but the diff shows
identical values. Microseconds have been added to the diff output for
`Time`.

By default `DateTime#inspect` outputs enough precision to prevent this
problem. `ActiveSupport` monkey patches `#inspect` to print a more human
readable but ambiguous representation. If `ActiveSupport` is defined a
custom format string is used for `DateTime` that has enough precision
to differentiate the two objects.

Fixes rspec/rspec-expectations#331
ec80b2c
@thomas-holmes
Member

I think this version might be a winner 👍

@myronmarston
Member

I think this version might be a winner

Yep, this is great. I left a suggestion but it's not a merge blocker -- let me know if that's not feasible and I'll merge away.

@thomas-holmes
Member

Ruby 1.8.7 Time objects don't support the %N token for strftime. 👎

@myronmarston myronmarston merged commit 70d1776 into rspec:master Jan 11, 2014

1 check passed

default The Travis CI build passed
Details
@myronmarston
Member

Thanks, @thomas-holmes!

@myronmarston myronmarston added a commit that referenced this pull request Jan 11, 2014
@myronmarston myronmarston Add Changelog for #416. 18ebf2a
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment