648255 - Intermittent failure in test_history_sidebar.js | Yesterday == Today crossing midnight

Status: RESOLVED FIXED

(Toolkit :: Places, defect)

Description

[Phil Ringnalda (:philor)]

I very much doubt it's coincidence that this test run started at 23:43 and finished at 00:09.

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1302158588.1302160038.1877.gz&fulltext=1
Rev3 Fedora 12 mozilla-central debug test xpcshell on 2011/04/06 23:43:08
s: talos-r3-fed-024

TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | test failed (with xpcshell return code: 0), see following log:
>>>>>>>
...
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [add_normalized_visit : 81] true == true
Found containers:
Yesterday
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
Last 7 days
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
March
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
February
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
January
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
December 2010
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
November 2010
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
Older than 6 months
TEST-PASS | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | [check_visit : 197] -1 == -1
Found containers:
Yesterday
TEST-UNEXPECTED-FAIL | /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | Yesterday == Today - See following stack:
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/head.js :: do_throw :: line 439
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/head.js :: do_check_eq :: line 491
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js :: fill_history :: line 156
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js :: run_test :: line 464
JS frame :: /home/cltbld/talos-slave/test/build/xpcshell/head.js :: _execute_test :: line 322
JS frame :: -e :: <TOP_LEVEL> :: line 1
TEST-INFO | (xpcshell/head.js) | exiting test

Comment 1

[Mounir Lamouri (:mounir)]

Ehsan, I believe these kind of situations should be mentioned in https://developer.mozilla.org/en/QA/Avoiding_intermittent_oranges

Comment 2

[Marco Bonardo [:mak]]

interesting that it never happened till now!
Sounds like the check runs just after midnight while addition runs just before it.

Comment 3

[(no longer active)]

(In reply to comment #1)
> Ehsan, I believe these kind of situations should be mentioned in
> https://developer.mozilla.org/en/QA/Avoiding_intermittent_oranges

I agree.  Would you mind adding this to the page, please?  :-)

Comment 4

[(no longer active)]

So, after looking into this, I don't think there is any good way to fix this failure, since we don't want to modify the behavior of places (which has its own concept of "now" which is out of the control of this test).

One way to address the orange would be to just abort the test is the we're past 23:50 or something.  Does that sounds totally insane?

Comment 5

[(no longer active)]

(In reply to comment #1)
> Ehsan, I believe these kind of situations should be mentioned in
> https://developer.mozilla.org/en/QA/Avoiding_intermittent_oranges

Added it to the wiki: <https://developer.mozilla.org/en/QA/Avoiding_intermittent_oranges#Tests_that_depend_on_the_current_time>

Comment 6

[Marco Bonardo [:mak]]

Hm so, we could maybe change visibleContainers to a getter, and have visible property on today depend on the fact it's still the same day or not...

Otherwise, your quick approach is fine, don't think that testing around midnight here is really that useful.

Comment 7

[(no longer active)]

Attachment: Patch (v1)

I'm lazy!

Comment 8

[Marco Bonardo [:mak]]

Comment on attachment 526447 [details] [diff] [review]
Patch (v1)

>diff --git a/toolkit/components/places/tests/unit/test_history_sidebar.js b/toolkit/components/places/tests/unit/test_history_sidebar.js

> // main
> function run_test() {
>   // Cleanup.
>   bh.removeAllPages();
>   remove_all_bookmarks();

While here, could you please remove these cleanup things?
They are useless in a xpcshell test, and removeAllPages is also dangerous (it's async and so this is calling for trouble).

Also the "// main" completely useless comment :)

Profit!

Comment 9

[(no longer active)]

http://hg.mozilla.org/mozilla-central/rev/ef29d1761717

Comment 10

[Daniel C]

I don't think this change is a good idea. It means that a change that genuinely breaks this behaviour might pass on the try server, but fail on checkin. Or pass on checkin, but fail on the subsequent checkin, causing unnecessary confusion. This is worse than the previous failure mode, which was rare and self-explanatory (Yesterday == Today).

The test should be made more robust if you want to avoid the rare orange, rather than just being skipped (it's now going to be skipped much more often than it was likely to fail as the definition of "dangerously close" is 10 minutes).

Comment 11

[(no longer active)]

(In reply to comment #10)
> I don't think this change is a good idea. It means that a change that genuinely
> breaks this behaviour might pass on the try server, but fail on checkin. Or
> pass on checkin, but fail on the subsequent checkin, causing unnecessary
> confusion. This is worse than the previous failure mode, which was rare and
> self-explanatory (Yesterday == Today).

I didn't like writing this patch for this exact reason, but the good news is that such a faulty patch would immediately be backed out on the next test run.  Also, the chance of a patch breaking this functionality landing and the test on all of our platforms running at the last 10 minutes of a day is really slim (though it's still possible).

> The test should be made more robust if you want to avoid the rare orange,
> rather than just being skipped (it's now going to be skipped much more often
> than it was likely to fail as the definition of "dangerously close" is 10
> minutes).

Unfortunately I don't have any better ideas on how to address this.  If you do, please let us know, and I will be happy to write a better patch.

Comment 12

[Daniel C]

If stopping intermittent oranges (however rare) is a priority then I can't think of a way to address the problem without rewriting the entire test.

Could you add an output message that at least states that although the test "passes" it hasn't actually been run? And I think you can safely reduce the time window, as the test is not going to take very long even on a heavily loaded VM.

Comment 13

[Mounir Lamouri (:mounir)]

Ehsan, could we do something like that:
- if midnight minus the current time isn't higher than the current test timeout, do nothing;
- otherwise, double the test timeout time and wait until we reach midnight.

The solution isn't ideal but at least, the tests should always be ran. This assumes we can change the test timeout dynamically during a test run (but I think I saw that once).

Comment 14

[Marco Bonardo [:mak]]

I don't think we should care about the above try fact, the probability that a developer runs the test locally with a pass, then try runs it again with a pass, and then it ails on central is practically none. Both of the first runs should be in the 10 minutes before midnight, and if a dev uses try only without running the tests locally before, as previously said, he is doing this wrong.

Comment 15

[(no longer active)]

(In reply to comment #12)
> If stopping intermittent oranges (however rare) is a priority

It's a priority, though not the highest one.

> Could you add an output message that at least states that although the test
> "passes" it hasn't actually been run? And I think you can safely reduce the
> time window, as the test is not going to take very long even on a heavily
> loaded VM.

Unfortunately the xpcshell test framework doesn't print any output messages for tests which are successful, so doing that wouldn't make any difference.  :(

Comment 16

[(no longer active)]

(In reply to comment #13)
> Ehsan, could we do something like that:
> - if midnight minus the current time isn't higher than the current test
> timeout, do nothing;
> - otherwise, double the test timeout time and wait until we reach midnight.
> 
> The solution isn't ideal but at least, the tests should always be ran. This
> assumes we can change the test timeout dynamically during a test run (but I
> think I saw that once).

This wouldn't work, because we would be racing against timer resolution, and we would fail that game some of the time.

Comment 17

[Daniel C]

(In reply to comment #15)
> Unfortunately the xpcshell test framework doesn't print any output messages for
> tests which are successful, so doing that wouldn't make any difference.  :(

Comment 0 shows output from the print() statements in the passing tests. Can't you do:

  if (nowObj.getHours() == 23 && nowObj.getMinutes() >= 50) {
    print("Skipping test as the definition of \"today\" might change midway through... Test started at: " + nowObj.toTimeString());
    return;
  }

?

Comment 18

[(no longer active)]

(In reply to comment #17)
> (In reply to comment #15)
> > Unfortunately the xpcshell test framework doesn't print any output messages for
> > tests which are successful, so doing that wouldn't make any difference.  :(
> 
> Comment 0 shows output from the print() statements in the passing tests. Can't
> you do:
> 
>   if (nowObj.getHours() == 23 && nowObj.getMinutes() >= 50) {
>     print("Skipping test as the definition of \"today\" might change midway
> through... Test started at: " + nowObj.toTimeString());
>     return;
>   }
> 
> ?

That output would *only* show up if the test fails.  This is what I meant in comment 15.

Comment 19

[Legacy TBPL/Treeherder Robot]

chris%pearce.org.nz
http://tinderbox.mozilla.org/showlog.cgi?log=Mozilla-Inbound/1309503457.1309506317.24733.gz
Rev3 WINNT 5.1 mozilla-inbound debug test xpcshell on 2011/06/30 23:57:37

s: talos-r3-xp-016
TEST-UNEXPECTED-FAIL | c:\talos-slave\test\build\xpcshell\tests\toolkit\components\places\tests\unit\test_history_sidebar.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | c:/talos-slave/test/build/xpcshell/tests/toolkit/components/places/tests/unit/test_history_sidebar.js | 8 == 9 - See following stack:

Comment 20

[Marco Bonardo [:mak]]

regarding comment 19, bug 576220 has been reopened.