Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul,test_install_app.xul | install time is after install() call OR install time is before install success

RESOLVED FIXED in Firefox 24

Status

RESOLVED FIXED
6 years ago
a year ago

People

(Reporter: mbrubeck, Assigned: marco)

Tracking

({intermittent-failure})

22 Branch
mozilla26
x86_64
Windows 8
intermittent-failure
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox24 fixed, firefox25 fixed, firefox26 fixed)

Details

(Whiteboard: [apps-automation:P3])

Attachments

(2 attachments, 1 obsolete attachment)

(Reporter)

Description

6 years ago
https://tbpl.mozilla.org/php/getParsedLog.php?id=21113131&tree=Firefox
WINNT 6.2 mozilla-central opt test mochitest-other on 2013-03-26 09:18:20 PDT for push 8d09f003e087

slave: t-w864-ix-026

09:24:47     INFO -  10182 INFO TEST-START | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul
09:24:47     INFO -  10183 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getInstalled() returns nothing
09:24:48     INFO -  10184 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | origin
09:24:48     INFO -  10185 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install origin
09:24:48     INFO -  10186 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call
09:24:48     INFO -  10187 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is before install success
09:24:48     INFO -  10188 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | manifest URL
09:24:48     INFO -  10189 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | manifest.name
09:24:48     INFO -  10190 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | manifest.installs_allowed_from
09:24:48     INFO -  10191 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getInstalled() returns app identical to install()
09:24:48     INFO -  10192 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getSelf() returns nothing (different origin)
09:24:48     INFO -  -- webapps.js uninstall http://test/chrome/dom/tests/mochitest/webapps/apps/launch_paths.webapp
09:24:48     INFO -  -- webapps.js uninstall http://test/chrome/dom/tests/mochitest/webapps/apps/launch_paths.webapp
09:24:48     INFO -  10193 INFO TEST-PASS | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | getInstalled() returns nothing again after uninstall
09:24:48     INFO -  10194 INFO TEST-END | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | finished in 185ms
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Probably has the same root cause as bug 856356.
See Also: → bug 856356
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)

Updated

6 years ago
Whiteboard: [apps-automation]

Updated

6 years ago
Whiteboard: [apps-automation] → [apps-automation:P3]
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Summary: Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call → Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call OR install time is before install success
Comment hidden (Treeherder Robot)
(Assignee)

Updated

5 years ago
Duplicate of this bug: 879210
(Assignee)

Comment 12

5 years ago
Created attachment 787062 [details] [diff] [review]
print_installtimes_test

This could help us understand what's going on.
Attachment #787062 - Flags: review?(fabrice)
(Assignee)

Updated

5 years ago
Summary: Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul | install time is after install() call OR install time is before install success → Intermittent TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/test_launch_paths.xul,test_install_app.xul | install time is after install() call OR install time is before install success
(Assignee)

Comment 13

5 years ago
The problem here could be that Date.now() is not precise enough, it's even not guaranteed to be monotonic. On my PC the difference between app.installTime and installSuccess is just 55 ms.
Comment hidden (Treeherder Robot)
Comment on attachment 787062 [details] [diff] [review]
print_installtimes_test

Review of attachment 787062 [details] [diff] [review]:
-----------------------------------------------------------------

That will not fix this bug, so keep open after landing that.
Attachment #787062 - Flags: review?(fabrice) → review+
(Assignee)

Updated

5 years ago
Keywords: checkin-needed
Whiteboard: [apps-automation:P3] → [apps-automation:P3][leave open]
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 23

5 years ago
I think fixing this bug is just impossible, because of Date.now().
(Reporter)

Comment 24

5 years ago
Why is "test_install_app.xul" mentioned in the bug summary?  All sixteen of the failures logged above are in test_launch_paths.xul.  Can we improve the logging in test_launch_paths.xul to help figure out what is causing this?

If it turns out to a problem with the system clock being non-monotonic, we could see if releng can investigate and fix the cause of that.
(Assignee)

Comment 25

5 years ago
(In reply to Matt Brubeck (:mbrubeck) from comment #24)
> Why is "test_install_app.xul" mentioned in the bug summary?  All sixteen of
> the failures logged above are in test_launch_paths.xul.  Can we improve the
> logging in test_launch_paths.xul to help figure out what is causing this?

The installTime test is exactly the same between test_launch_path.xul and test_install_app.xul, this is why I duped bug 879210 to this bug.

See bug 879210 comment 5 for a more meaningful error log.
Comment hidden (Treeherder Robot)
(Reporter)

Comment 27

5 years ago
(In reply to Marco Castelluccio [:marco] from comment #25)
> The installTime test is exactly the same between test_launch_path.xul and
> test_install_app.xul, this is why I duped bug 879210 to this bug.
> 
> See bug 879210 comment 5 for a more meaningful error log.

Ah, thanks! I missed that.

(In reply to TinderboxPushlog Robot from comment #5)
> 10456 ERROR TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/chrome/dom/tests/mochitest/webapps/
> test_install_app.xul | install time (1376091000066) is before install
> success (1376091000058)

So, assuming the code is correct (I think it is), the clock on this slave went backwards by at least 8 ms, presumably from NTP or similar software adjusting for skew.  Maybe we should change the test to use fuzzy comparisons, e.g. "app.installTime <= installSuccess + 1000" assuming that the clock will not jump by more that that, or at least won't do it nearly as often.  Then we are still testing that installTime is basically correct, without exposing ourselve as much to the vagaries of Date.now().
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(In reply to Matt Brubeck (:mbrubeck) from comment #27)
> So, assuming the code is correct (I think it is), the clock on this slave
> went backwards by at least 8 ms, presumably from NTP or similar software
> adjusting for skew.  Maybe we should change the test to use fuzzy
> comparisons, e.g. "app.installTime <= installSuccess + 1000" assuming that
> the clock will not jump by more that that, or at least won't do it nearly as
> often.  Then we are still testing that installTime is basically correct,
> without exposing ourselve as much to the vagaries of Date.now().

Marco, can you try this?
Flags: needinfo?(mcastelluccio)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 54

5 years ago
Created attachment 795597 [details] [diff] [review]
Patch
Attachment #795597 - Flags: review?(fabrice)
Flags: needinfo?(mcastelluccio)
(Assignee)

Updated

5 years ago
Attachment #787062 - Flags: checkin+
(Assignee)

Updated

5 years ago
Whiteboard: [apps-automation:P3][leave open] → [apps-automation:P3]
Assignee: nobody → mcastelluccio
status-firefox24: --- → affected
status-firefox25: --- → affected
status-firefox26: --- → affected
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment on attachment 795597 [details] [diff] [review]
Patch

Review of attachment 795597 [details] [diff] [review]:
-----------------------------------------------------------------

In both files: make 1000 a constant and not a literal, and I think it's too much based on the logs we now get. I'd like to try with 250 instead.

r=me with this changes
Attachment #795597 - Flags: review?(fabrice) → review+
(Assignee)

Comment 61

5 years ago
Created attachment 796204 [details] [diff] [review]
Patch

Carrying r+.
Attachment #795597 - Attachment is obsolete: true
Attachment #796204 - Flags: review+
(Assignee)

Updated

5 years ago
Keywords: checkin-needed
A reminder - your commit messages should be describing what the patch is actually doing, not just restating the bug title.
https://hg.mozilla.org/integration/fx-team/rev/f975e58efdbc
Keywords: checkin-needed
Whiteboard: [apps-automation:P3] → [apps-automation:P3][fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/f975e58efdbc
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [apps-automation:P3][fixed-in-fx-team] → [apps-automation:P3]
Target Milestone: --- → mozilla26
https://hg.mozilla.org/releases/mozilla-aurora/rev/e1ace59a97de
https://hg.mozilla.org/releases/mozilla-beta/rev/c2ff0ee58628
status-firefox24: affected → fixed
status-firefox25: affected → fixed
status-firefox26: affected → fixed

Updated

a year ago
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.