Recurrences (tests?) have an end-of-day edge case

[dnrce]

See https://travis-ci.org/TracksApp/tracks/jobs/36919173 which ran at 2014-10-02T22:39:54Z.

Run options: --seed 4101

# Running:

..............................................................................................F.................................................................................................................................................................................F................................................................................F....................................................................................................................................................................................................................................................................

Finished in 65.736660s, 9.3403 runs/s, 25.9368 assertions/s.

  1) Failure:
RecurringTodos::DailyRepeatPatternTest#test_daily_every_day [/home/travis/build/TracksApp/tracks/test/models/recurring_todos/daily_repeat_pattern_test.rb:53]:
Expected: "02-10-14"
  Actual: "03-10-14"


  2) Failure:
UserTest#test_find_and_activate_deferred_todos_that_are_ready [/home/travis/build/TracksApp/tracks/test/models/user_test.rb:215]:
Expected: 0
  Actual: 1


  3) Failure:
TodoTest#test_load [/home/travis/build/TracksApp/tracks/test/models/todo_test.rb:25]:
Expected: "2014-09-26 00:00"
  Actual: "2014-09-25 00:00"

614 runs, 1705 assertions, 3 failures, 0 errors, 0 skips

From the Travis log, the actual start and stop times of the rake ci task were Thu, 02 Oct 2014 22:44:55 GMT and Thu, 02 Oct 2014 23:02:56 GMT, respectively.

[lrbalt]

that could well be the problem. I do not think we set the time when we use Travel. I'll look into this before 2.3final, although this is a false positive I presume

[dnrce]

A quick look at the failing tests makes me think time travel is not the right answer here.

Could you please do this as a PR before merging anything into 2.3? I'd like the chance to review it.

[matjack1]

Did you manage to reproduce the bug? I tried changing my system clock back to the error state, changing the time zone and changing the time_zone setting in the site.yml. I tried various permutations of these things without any success. Any other idea on how to reproduce it?

[dnrce]

I don't think time_zone in site.yml will have an effect, but an easy way to override the system time zone is to set the TZ environment variable before running the tests. I haven't tried to reproduce this myself yet.

[matjack1]

I tried with the following three commands:

➜  tracks git:(master) date
Thu  2 Oct 2014 22:36:45 BST
➜  tracks git:(master) TZ="Europe/London" rake test
Run options: --seed 40660

# Running:

.........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

Finished in 31.126703s, 19.8222 runs/s, 52.9128 assertions/s.

617 runs, 1647 assertions, 0 failures, 0 errors, 0 skips


➜  tracks git:(master) date
Thu  2 Oct 2014 16:35:26 CDT
➜  tracks git:(master) TZ="America/Chicago" rake test
Run options: --seed 45799

# Running:

.........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

Finished in 31.712007s, 19.4564 runs/s, 51.9362 assertions/s.

617 runs, 1647 assertions, 0 failures, 0 errors, 0 skips


➜  tracks git:(master) date
Fri  3 Oct 2014 05:34:04 WST
➜  tracks git:(master) TZ="Australia/Perth" rake test
Run options: --seed 5583

# Running:

.........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

Finished in 31.408086s, 19.6446 runs/s, 52.4387 assertions/s.

617 runs, 1647 assertions, 0 failures, 0 errors, 0 skips

Between each test I was changing my local timezone (as you can see by the date result). I really can't understand what was going on :(

[lrbalt]

I have seen test failures when the edge-case was an end-of-month in the middle of the week or something like that. So these tests rule out timezone issues, but not other edge-cases

[dnrce]

While I still think this is a real bug due to the fact that it happened in two simultaneous builds, I'm unable to reproduce it using libfaketime or by running in a VM with an adjusted clock.

I was able to reproduce this bug in a VM with a disconnected clock:

$ sudo date -s '2014-10-02T23:00:00Z' && bundle exec rake test TESTOPTS='--seed 4101' ; date
Thu Oct  2 23:00:00 UTC 2014
Run options: --seed 4101

# Running:

.....................................................................................................................................................................................................................................................F...............................................F............................................................................................................................................................................................................................................F...................................................................................

Finished in 45.414799s, 13.5198 runs/s, 37.5428 assertions/s.

  1) Failure:
UserTest#test_find_and_activate_deferred_todos_that_are_ready [~/src/tracks/test/models/user_test.rb:215]:
Expected: 0
  Actual: 1


  2) Failure:
RecurringTodos::DailyRepeatPatternTest#test_daily_every_day [~/src/tracks/test/models/recurring_todos/daily_repeat_pattern_test.rb:53]:
Expected: "02-10-14"
  Actual: "03-10-14"


  3) Failure:
TodoTest#test_load [~/src/tracks/test/models/todo_test.rb:25]:
Expected: "2014-09-26 00:00"
  Actual: "2014-09-25 00:00"

614 runs, 1705 assertions, 3 failures, 0 errors, 0 skips
Thu Oct  2 23:00:51 UTC 2014

[dnrce]

Once I got the conditions right I was also able to reproduce this on my Mac with libfaketime:

$ TZ=UTC FAKETIME="@2014-10-02 23:00:00" bundle exec rake test
Run options: --seed 27192

# Running:

............................................................................................................................................................................................................................................................................................................................................................................................................................................................F...................F....................................F................................................................................................................

Finished in 25.690247s, 23.9001 runs/s, 66.3676 assertions/s.

  1) Failure:
TodoTest#test_load [~/src/tracks/test/models/todo_test.rb:25]:
Expected: "2014-09-26 00:00"
  Actual: "2014-09-25 00:00"


  2) Failure:
RecurringTodos::DailyRepeatPatternTest#test_daily_every_day [~/src/tracks/test/models/recurring_todos/daily_repeat_pattern_test.rb:53]:
Expected: "02-10-14"
  Actual: "03-10-14"


  3) Failure:
UserTest#test_find_and_activate_deferred_todos_that_are_ready [~/src/tracks/test/models/user_test.rb:215]:
Expected: 0
  Actual: 1

614 runs, 1705 assertions, 3 failures, 0 errors, 0 skips

[dnrce]

Also note that although the Travis build was on the master branch, I have confirmed the bug in 2.3_branch.

[matjack1]

Thanks @dnrce I can reproduce the bug now. BTW now I experience a fourth failure:

  1) Failure:
UserTest#test_find_and_activate_deferred_todos_that_are_ready [/Users/matjack1/src/tracks/test/models/user_test.rb:214]:
Expected: 0
  Actual: 1


  2) Failure:
TodoTest#test_load [/Users/matjack1/src/tracks/test/models/todo_test.rb:25]:
Expected: "2014-09-26 00:00"
  Actual: "2014-09-25 00:00"


  3) Failure:
PreferencesControllerTest#test_calling_render_date_format_returns_date [/Users/matjack1/src/tracks/test/controllers/preferences_controller_test.rb:19]:
Expected: "Sunday 1969"
  Actual: "Tuesday 2086"


  4) Failure:
RecurringTodos::DailyRepeatPatternTest#test_daily_every_day [/Users/matjack1/src/tracks/test/models/recurring_todos/daily_repeat_pattern_test.rb:53]:
Expected: "02-10-14"
  Actual: "03-10-14"

both from master and from 2.3 branch. Isn't that strange that you don't experience the same error? Am I doing something weird?

[dnrce]

@matjack1 That's a weird one. Are you using libfaketime?

[dnrce]

@matjack1 I'm also getting seemingly random failures of PreferencesControllerTest#test_calling_render_date_format_returns_date. I'm willing to write it off as libfaketime strangeness for the time being.

[matjack1]

Yes @dnrce I'm using libfaketime as well. It looks like a library "strangeness", especialy if you look to the strange dates...

[matjack1]

The PR #1743 should address the test problems. Most of the problems come from the time zone handling that causes problems near the end of the day (I reckon).

If you have any doubt we can continue the discussion directly in the code maybe.