465510 - random failures on test_database_sync_after_addVisit.js

Status: RESOLVED FIXED

(Toolkit :: Places, defect)

Description

[Marco Bonardo [:mak]]

i see random failures for this test on the tinderboxes, especially on windows, see for example
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1227011143.1227014283.15580.gz

i suppose this is mostly a timer issue due to the sync timer being low (1s). Hwv we should investigate on why that happens.

Comment 1

[:Gavin Sharp [email: [e-mail]]]

Another occurence:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1228183105.1228186110.25235.gz&fulltext=1#err0

Comment 2

[Marco Bonardo [:mak]]

i think we can rewrite the test to wait for sync notification and check elapsed time, that should solve the randomness.

Comment 3

[Marco Bonardo [:mak]]

Attachment: patch

this should solve the randomness

Comment 4

[Shawn Wilsher :sdwilsh]

Comment on attachment 351681 [details] [diff] [review]
patch

>+++ b/toolkit/components/places/tests/sync/test_database_sync_after_addVisit.js
>+var observer = {
>+  visitId: -1,
>+  visitTime: null,
>+  observe: function(aSubject, aTopic, aData) {
>+    if (aTopic == kSyncFinished && this.visitId != -1) {
>+      // remove the observer, we don't need to observe sync on quit
>+      os.removeObserver(this, kSyncFinished);
>+      // sanity check that sync has happened in a max of SYNC_INTERVAL * 5
>+      do_check_true(Date.now() - this.visitTime < SYNC_INTERVAL * 5);
This is still prone to failure.  Just drop it.

>+// Used to update observer visitId
>+var historyObserver = {
>+  onVisit: function(aURI, aVisitId, aTime, aSessionId, aReferringId,
>+                    aTransitionType, aAdded) {
>+    observer.visitTime = aTime;
>+    observer.visitId = aVisitId;
>+    hs.removeObserver(this, false);
There is no need to track visit time given my previous comment, but note that visitTime is a PRTime, which is in microseconds, and Date.now() is in milliseconds.

>   // Now add the visit
>-  let id = hs.addVisit(uri(TEST_URI), Date.now() * 1000, null,
>-                       hs.TRANSITION_TYPED, false, 0);
>+  hs.addVisit(uri(TEST_URI), Date.now() * 1000, null,
>+              hs.TRANSITION_TYPED, false, 0);
It'll still be nice to sanity check the id here, so you should stored it and check that it's the same in onVisit.

I'm really concerned that somehow our nsITimer orderings got interleaved.  It doesn't seem to make a whole lot of sense to me, and these tinderbox machines must be running incredibly slow.  *sigh*

Comment 5

[Marco Bonardo [:mak]]

(In reply to comment #4)
> (From update of attachment 351681 [details] [diff] [review])
> >+++ b/toolkit/components/places/tests/sync/test_database_sync_after_addVisit.js
> >+var observer = {
> >+  visitId: -1,
> >+  visitTime: null,
> >+  observe: function(aSubject, aTopic, aData) {
> >+    if (aTopic == kSyncFinished && this.visitId != -1) {
> >+      // remove the observer, we don't need to observe sync on quit
> >+      os.removeObserver(this, kSyncFinished);
> >+      // sanity check that sync has happened in a max of SYNC_INTERVAL * 5
> >+      do_check_true(Date.now() - this.visitTime < SYNC_INTERVAL * 5);
> This is still prone to failure.  Just drop it.

yes and no, i mean, it could fail if the statements would be damn slow or the system highly overloaded, but calculating 5 time the sync should catch all of them.
Instead VM timers would not hit this since at last if the timer does not proceed the check is always true... Hwv i agree to drop it.


> visitTime is a PRTime, which is in microseconds, and Date.now() is in
> milliseconds.

i was sure to have done the conversion, i was probably drunk then, will come with both patches updated to drop timer

Comment 6

[Marco Bonardo [:mak]]

Attachment: patch v1.1

(In reply to comment #4)
> (From update of attachment 351681 [details] [diff] [review])
> >+++ b/toolkit/components/places/tests/sync/test_database_sync_after_addVisit.js
> >+      // sanity check that sync has happened in a max of SYNC_INTERVAL * 5
> >+      do_check_true(Date.now() - this.visitTime < SYNC_INTERVAL * 5);
> This is still prone to failure.  Just drop it.

done

> >+  onVisit: function(aURI, aVisitId, aTime, aSessionId, aReferringId,
> >+                    aTransitionType, aAdded) {
> >+    observer.visitTime = aTime;
> >+    observer.visitId = aVisitId;
> >+    hs.removeObserver(this, false);
> There is no need to track visit time

removed

> >   // Now add the visit
> >-  let id = hs.addVisit(uri(TEST_URI), Date.now() * 1000, null,
> >-                       hs.TRANSITION_TYPED, false, 0);
> >+  hs.addVisit(uri(TEST_URI), Date.now() * 1000, null,
> >+              hs.TRANSITION_TYPED, false, 0);
> It'll still be nice to sanity check the id here, so you should stored it and
> check that it's the same in onVisit.

I can't check in onVisit because it is called before we return the value, hwv i've added a sanity check in the observer for it

Comment 7

[Shawn Wilsher :sdwilsh]

Comment on attachment 351897 [details] [diff] [review]
patch v1.1

r=sdwilsh

Comment 8

[Marco Bonardo [:mak]]

pushed to trunk:
http://hg.mozilla.org/mozilla-central/rev/b6aec13be588

Comment 9

[Marco Bonardo [:mak]]

pushed to 1.9.1 branch:
http://hg.mozilla.org/releases/mozilla-1.9.1/rev/c9a496856722