Closed Bug 854975 Opened 12 years ago Closed 11 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)

Product:
Core Graveyard
Component:
DOM: Apps
Version:
22 Branch
Platform:
x86_64
Windows 8
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox24 fixed, firefox25 fixed, firefox26 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla26
Tracking Flags:
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)

print_installtimes_test
1.44 KB, patch
fabrice
: review+
marco
: checkin+
Details | Diff | Splinter Review
Patch
3.12 KB, patch
marco
: review+
Details | Diff | Splinter Review
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
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
status-firefox24: --- → affected
status-firefox25: --- → affected
status-firefox26: --- → affected
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 Patch — — Splinter 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: 11 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.

Attachment

General

Creator:
Created:
Updated:
Size: