Time#travel should be side-effect free and not resume system clock

[mkobit]

I noticed we had some tests that measure elapsed time, and use Timecop in tests to check that the measuring results are accurate. The tests were measuring time passed in milliseconds. Then, I noticed that those tests would periodically fail. It seemed like Timecop was not deterministically advancing the test clock forward. Here is an example test spec named mkobit_spec.rb using RSpec and Timecop 0.9.4:

require 'rspec'
require 'timecop'

describe 'Mkobit' do

  N_ITERATIONS = 4_000
  SLEEP_DUR = 0.002

  (1..N_ITERATIONS).each do |n|
    it "advance int test #{n}" do
      sleep(SLEEP_DUR) # add some jitter in between tests
      Timecop.freeze do
        s = Time.now
        adv = 10 # 10 seconds
        Timecop.travel(adv)
        e = Time.now
        d = e - s
        d1k = d * 1_000
        ms = d1k.to_i
        expect(ms).to eq(10_000), "start=(#{s}, #{s.to_f}), adv=(#{adv}), end=(#{e}, #{e.to_f}), diff=(#{d}, d1k:#{d1k})"
      end
    end
  end
end

I then started a Ruby container with this file:

docker container run -w /tmp --mount type=bind,source="$(pwd)/spec/mkobit_spec.rb",target=/tmp/mkobit_spec.rb -it --rm ruby:3.0.1 bash

gem install rspec

Fetching rspec-3.10.0.gem
Fetching diff-lcs-1.4.4.gem
Fetching rspec-mocks-3.10.2.gem
Fetching rspec-expectations-3.10.1.gem
Fetching rspec-core-3.10.1.gem
Fetching rspec-support-3.10.2.gem
Successfully installed rspec-support-3.10.2
Successfully installed diff-lcs-1.4.4
Successfully installed rspec-mocks-3.10.2
Successfully installed rspec-expectations-3.10.1
Successfully installed rspec-core-3.10.1
Successfully installed rspec-3.10.0
6 gems installed

gem install timecop

Fetching timecop-0.9.4.gem
Successfully installed timecop-0.9.4
1 gem installed
root@d5dc18449b51:/tmp#

Then, I executed the spec:

• rspec mkobit_spec.rb

Which, surprisingly, led to some failures. I expect every time travel to move exactly 10 seconds (10,000 ms), but some do not. For example, here is a sample output from 1 execution:

Failures:

Test Fail Log Example

  1) Mkobit advance int test 180
     Failure/Error: expect(ms).to eq(10_000), "start=(#{s}, #{s.to_f}), adv=(#{adv}), end=(#{e}, #{e.to_f}), diff=(#{d}, d1k:#{d1k})"
       start=(2021-04-22 15:42:21 +0000, 1619106141.5444498), adv=(10), end=(2021-04-22 15:42:31 +0000, 1619106151.5472612), diff=(10.002811495, d1k:10002.811495)
     # ./mike_kobit_spec.rb:24:in `block (4 levels) in <top (required)>'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:201:in `travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:129:in `send_travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:50:in `freeze'
     # ./mike_kobit_spec.rb:16:in `block (3 levels) in <top (required)>'

  2) Mkobit advance int test 1448
     Failure/Error: expect(ms).to eq(10_000), "start=(#{s}, #{s.to_f}), adv=(#{adv}), end=(#{e}, #{e.to_f}), diff=(#{d}, d1k:#{d1k})"
       start=(2021-04-22 15:42:25 +0000, 1619106145.4278185), adv=(10), end=(2021-04-22 15:42:35 +0000, 1619106155.431302), diff=(10.003483684, d1k:10003.483684)
     # ./mike_kobit_spec.rb:24:in `block (4 levels) in <top (required)>'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:201:in `travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:129:in `send_travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:50:in `freeze'
     # ./mike_kobit_spec.rb:16:in `block (3 levels) in <top (required)>'

  3) Mkobit advance int test 1454
     Failure/Error: expect(ms).to eq(10_000), "start=(#{s}, #{s.to_f}), adv=(#{adv}), end=(#{e}, #{e.to_f}), diff=(#{d}, d1k:#{d1k})"
       start=(2021-04-22 15:42:25 +0000, 1619106145.4551609), adv=(10), end=(2021-04-22 15:42:35 +0000, 1619106155.4565322), diff=(10.001371398, d1k:10001.371398)
     # ./mike_kobit_spec.rb:24:in `block (4 levels) in <top (required)>'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:201:in `travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:129:in `send_travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:50:in `freeze'
     # ./mike_kobit_spec.rb:16:in `block (3 levels) in <top (required)>'

  4) Mkobit advance int test 3714
     Failure/Error: expect(ms).to eq(10_000), "start=(#{s}, #{s.to_f}), adv=(#{adv}), end=(#{e}, #{e.to_f}), diff=(#{d}, d1k:#{d1k})"
       start=(2021-04-22 15:42:32 +0000, 1619106152.6589386), adv=(10), end=(2021-04-22 15:42:42 +0000, 1619106162.6608737), diff=(10.00193493, d1k:10001.93493)
     # ./mike_kobit_spec.rb:24:in `block (4 levels) in <top (required)>'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:201:in `travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:129:in `send_travel'
     # /usr/local/bundle/gems/timecop-0.9.4/lib/timecop/timecop.rb:50:in `freeze'
     # ./mike_kobit_spec.rb:16:in `block (3 levels) in <top (required)>'

Finished in 12.51 seconds (files took 0.21632 seconds to load)
4000 examples, 4 failures

Failed examples:

rspec './mike_kobit_spec.rb[1:180]' # Mkobit advance int test 180
rspec './mike_kobit_spec.rb[1:1448]' # Mkobit advance int test 1448
rspec './mike_kobit_spec.rb[1:1454]' # Mkobit advance int test 1454
rspec './mike_kobit_spec.rb[1:3714]' # Mkobit advance int test 3714

Note that the output will be different every time. Even when doing a Time.freeze(Time.at(<fixed point>)), some tests will still fail. I would expect that s and e would effectively be exactly 10 seconds apart.

It appears that time travel with Timecop does not deterministically move the test clock forward.

[mkobit]

It seems like Timecop.travel might "unfreeze" the clock, even though it is in a Timecop.freeze block

[joshuacronemeyer]

Hi mkobit, travel and freeze don't really work together the way you are expecting. Calling Timecop.travel puts a 'travel' type time mock at the top of the stack... and the travel type mock lets the clock run. It isn't frozen. I do see why this is confusing and isn't what you expect.

[mkobit]

Thanks, @joshuacronemeyer . Doing the same example replacing Timecop with Rails' TimeHelpers does perform the way I would expect it to (time is exactly 10.0 ms every single execution). Other libraries with fake clocks like Guava's FakeTicker, Kotlin's upcoming standard library TestTimeSource, and the Rails example above all have the notion of the test clock being advanced forward through code rather than global state change. The Time#travel is unexpected, and I wonder if others have ran into the same issue.

Would it make sense to change Time#travel to be consistent with other libraries and user expectations? Does Time#travel implicitly "unfreezing" the test clock have real use cases?

[joshuacronemeyer]

@mkobit I'm a relatively new contributor/maintainer so I don't have much context why travel has that behavior. I do agree that it is surprising behavior. Do you have interest in working on this?

I think we'd want to make the change in a way that wouldn't immediately break things for people who might depend on that behavior. One path forward could be a configuration option that provides the new behavior, and then we could eventually make that option the default on the next major release.

We could follow the pattern of Timecop safe mode, so you'd do something like this in your test helper or spec helper:

#Configure Timecop so #travel will not unfreeze time
Timecop.travel_unfreezes = false

In the meantime maybe @travisjeffery can chime in if he has context on this behavior.

[jtrupiano]

Just use #freeze instead of #travel. #travel by definition allows the clock to continue. That's the difference between the two methods! This is useful when you need to test that thing A occurred before or after thing B.

On Wed, Apr 28, 2021 at 8:46 AM Josh @.***> wrote:

@mkobit https://github.com/mkobit I'm a relatively new contributor/maintainer so I don't have much context why travel has that behavior. I do agree that it is surprising behavior. Do you have interest in working on this?

I think we'd want to make the change in a way that wouldn't immediately break things for people who might depend on that behavior. One path forward could be a configuration option that provides the new behavior, and then we could eventually make that option the default on the next major release.

We could follow the pattern of Timecop safe mode, so you'd do something like this in your test helper or spec helper:

#Configure Timecop so #travel will not unfreeze time Timecop.travel_unfreezes = false

In the meantime maybe @travisjeffery https://github.com/travisjeffery can chime in if he has context on this behavior.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/travisjeffery/timecop/issues/301#issuecomment-828563613, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAADAK63N7KHSMTZ5WAPXMTTLAUUNANCNFSM43MX4YGQ .

[mkobit]

I believe my gripe is that Time#travel should not resume the clock. This behavior is especially unexpected inside a Time#freeze block, where my belief is that I am in control of the clock. I think the existing behavior is counter-intuitive. My belief is that any user who wants to move the clock forward will move the clock forward explicitly. I can't personally think of any use cases I have had in testing time dependent code where I wanted the test clock to continue rolling forward after advancing it. There may be a different expectation when using Timecop, but at least seeing how other libraries in other spaces are doing it as well as Rails in the Ruby ecosystem seems aligned with that. My expectation from a user perspective is that advancing the test-clock using Time#travel should be side-effect free.

Timecop.freeze do
  t1 = Time.now 
  Timecop.travel(5) # 5 seconds
  sleep(5) # thread sleep to demonstrate problem
  t2 = Time.now
  expect(t2 - t1).to eq(5.0) # actual is 10.xxxxx
end

I think the suggestion is to do something like:

Timecop.freeze do
  t1 = Time.now 
  Timecop.freeze(Time.now + 5) # 5 seconds
  sleep(5) # thread sleep to demonstrate problem
  t2 = Time.now
  expect(t2 - t1).to eq(5.0)
end

Which I don't believe is the most user friendly API.

I'll update the title of this issue to accurately reflect the original request, and then a decision on the above can be considered either way.

[jtrupiano]

#travel and #freeze were explicitly designed as two different ways to meddle with time. I used each behavior for distinct purposes, so I'm confused why you want to eliminate the one that you don't personally use. Freeze is explicit; we're going to literally stop time. Travel on the other hand doesn't connote that time is going to come to a standstill. When I time travel (e.g. in a sci-fi novel) and arrive in my new time, time isn't frozen, it is moving forward. So semantically they seem pretty sensical to me.

Furthermore, when I move deeper into the block stack in ruby, I expect the current block's localized rules to be in place, not the outer block's. This is fairly idiomatic ruby as I recall it. So even though the outer block has frozen it, the current local block has explicitly (by choice of the code's author) used a method that unfreezes it, hence the behavior we see.

While I am the original author of timecop (circa 13 years ago), it has been 8+ years since I handed off maintenance to other developers, so I'll let y'all decide how you want to handle it. But as a user I would be confused if this behavior were changed as you are requesting.

-John

On Wed, Apr 28, 2021 at 12:57 PM Mike Kobit @.***> wrote:

I believe my gripe is that Time#travel should not resume the clock. This behavior is especially unexpected inside a Time#freeze block, where my belief is that I am in control of the clock. I think the existing behavior is counter-intuitive. My belief is that any user who wants to move the clock forward will move the clock forward explicitly. I can't personally think of any use cases I have had in testing time dependent code where I wanted the test clock to continue rolling forward after advancing it. There may be a different expectation when using Timecop, but at least seeing how other libraries in other spaces are doing it as well as Rails in the Ruby ecosystem seems align with that. My expectation from a user perspective is that advancing the test-clock using Time#travel should be side-effect free.

Timecop.freeze do t1 = Time.now Timecop.travel(5) # 5 seconds sleep(5) # thread sleep to demonstrate problem t2 = Time.now expect(t2 - t1).to eq(5.0) # actual is 10.xxxxxend

I think the suggestion is to do something like:

Timecop.freeze do t1 = Time.now Timecop.freeze(Time.now + 5) # 5 seconds sleep(5) # thread sleep to demonstrate problem t2 = Time.now expect(t2 - t1).to eq(5.0)end

Which I don't believe is the most user friendly API.

I'll update the title of this issue to accurately reflect the original request, and then a decision on the above can be considered either way.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/travisjeffery/timecop/issues/301#issuecomment-828737091, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAADAKYXRDZJ3DMJBR6LUV3TLBSCVANCNFSM43MX4YGQ .

[mkobit]

I used each behavior for distinct purposes, so I'm confused why you want to eliminate the one that you don't personally use.

This is a fair critique. I have preexisting expectations for this library based on others I have used, but Timecop may have different use cases it is supporting.

Travel on the other hand doesn't connote that time is going to come to a standstill. When I time travel (e.g. in a sci-fi novel) and arrive in my new time, time isn't frozen, it is moving forward.

My expectation is that if I pause the clock and then add something to it, it should remain paused. For example:

• If I pause YouTube, and then hit my arrow key right to advance forward or backwards, it remains paused
• If I pause my Spotify song in progress, and then click anywhere in the song, it remains paused at the point in the song I went to
• If I pause a podcast on my Podcast Addict app and hit either the +30s or -15s buttons, the podcast remains paused at the moment that was jumped to

I saw the same behavior with Reddit, Audible, Prime Video, and other apps and media I could find. I think might be another reason why I have this expectation of the clock not resuming on the travel call baked in. I can understand your sci-fi comparison, but I have a different expectation from when I stop the clock.

But as a user I would be confused if this behavior were changed as you are requesting.

To me, that is the main argument to retaining the current behavior. I think a flag could be potentially useful, but it might also be confusing to offer another global setting that alters the overall behavior. This library has been around with the current behavior for a long time, and changing it to something else may surprise users.

However, I think new users will be surprised by the current behavior. If they have the option, they might be better suited to use Rails' Time helpers.

As you mentioned, totally up to the maintainers on if this issue has merit or not.

[ShadSterling]

I just found this looking for a way to restore the system clock within a nested block, like

Timecop.travel( some_time ) do
    Time.now #=> just after some_time
    Timecop.system do
        Time.now #=> system time
    end
    Time.now #=> shortly after some_time
end

---

I think the difference in expectation in the above conversation is about what should change when nesting. To me, the obvious expectation is that a nested call makes changes relative to the containing context and nothing outside of that, and that

• freeze stops the clock from advancing within the block (optionally also setting the time within the block)
• travel sets the time at the beginning of the block (without changing whether or not the clock is frozen)

The other interpretation seems to be

• travel ensures that the clock advances within the block (optionally also setting the time at the beginning of the block)

So the problem is that the name and documentation aren't clear about whether travel refers to changing the time or to the clock advancing.

My inclination would be to resolve the ambiguity by deprecating travel and replacing it with two distinct methods that match the different expectations, maybe flow and set

So the options would be something like

• freeze stops the clock from advancing within the block (optionally also setting the time within the block)
• flow ensures that the clock advances within the block (optionally also setting the time at the beginning of the block and/or the flow rate/scale)
• set sets the time at the beginning of the block (optionally also setting the flow rate/scale)
• system uses the system clock within the block

---

My use case for nesting system time inside of randomized time is for a test suite where I want to set the time to a random time for each test, but I have a few tests that will take a long time to refactor to inject the random time into the mock data, so I want to go back to system time for just those tests. For now I've addressed that by switching on test metadata.

[joshuacronemeyer]

closing this discussion for lack of activity.