Closed Bug 854975 Opened 7 years ago Closed 6 years ago

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

Categories

(Core Graveyard :: DOM: Apps, defect)

22 Branch
x86_64
Windows 8
defect
Not set

Tracking

(firefox24 fixed, firefox25 fixed, firefox26 fixed)

RESOLVED FIXED
mozilla26
Tracking Status
firefox24 --- fixed
firefox25 --- fixed
firefox26 --- fixed

People

(Reporter: mbrubeck, Assigned: marco)

References

Details

(Keywords: intermittent-failure, Whiteboard: [apps-automation:P3])

Attachments

(2 files, 1 obsolete file)

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
Probably has the same root cause as bug 856356.
See Also: → 856356
Whiteboard: [apps-automation]
Whiteboard: [apps-automation] → [apps-automation:P3]
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
Duplicate of this bug: 879210
This could help us understand what's going on.
Attachment #787062 - Flags: review?(fabrice)
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
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 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+
Keywords: checkin-needed
Whiteboard: [apps-automation:P3] → [apps-automation:P3][leave open]
I think fixing this bug is just impossible, because of Date.now().
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.
(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.
(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().
(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)
Attached patch Patch (obsolete) — Splinter Review
Attachment #795597 - Flags: review?(fabrice)
Flags: needinfo?(mcastelluccio)
Attachment #787062 - Flags: checkin+
Whiteboard: [apps-automation:P3][leave open] → [apps-automation:P3]
Assignee: nobody → mcastelluccio
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+
Attached patch PatchSplinter Review
Carrying r+.
Attachment #795597 - Attachment is obsolete: true
Attachment #796204 - Flags: review+
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
Closed: 6 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [apps-automation:P3][fixed-in-fx-team] → [apps-automation:P3]
Target Milestone: --- → mozilla26
Product: Core → Core Graveyard
You need to log in before you can comment on or make changes to this bug.