Closed Bug 1467352 Opened 3 years ago Closed 3 years ago

Intermittent tier2 toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js | xpcshell return code: 0

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(firefox63 fixed)

RESOLVED FIXED
mozilla63
Tracking Status
firefox63 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: rpl)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Filed by: ncsoregi [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=182185505&repo=mozilla-central

https://queue.taskcluster.net/v1/task/b5EoSEzDT22hUB_ZkG757A/runs/0/artifacts/public/logs/live_backing.log

00:48:11     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js
00:48:36  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js | xpcshell return code: 0
00:48:36     INFO -  TEST-INFO took 25597ms
00:48:36     INFO -  >>>>>>>
00:48:36     INFO -  PID 6232 | [6232, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file z:/build/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2678
00:48:36     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
00:48:36     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
00:48:36     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
00:48:36     INFO -  running event loop
00:48:36     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js | Starting check_remote
00:48:36     INFO -  (xpcshell/head.js) | test check_remote pending (2)
00:48:36     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js | check_remote - [check_remote : 1426] useRemoteWebExtensions matches - true == true
There are 33 failures for the past week, only windows10-64-ccov platform, debug build type.

Recent log: https://treeherder.mozilla.org/logviewer.html#?job_id=182930789&repo=mozilla-central&lineNumber=2800

17:04:18     INFO -  Retrying tests that failed when run in parallel.
17:04:19     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms.js
17:04:37     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms.js | took 18937ms
17:04:37     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms_periodic.js
17:04:56     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms_periodic.js | took 18501ms
17:04:56     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms_does_not_fire.js
17:05:12     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_alarms_does_not_fire.js | took 16109ms
17:05:12     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentscript_async_loading.js
17:05:45     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_contentscript_async_loading.js | took 32901ms
17:05:45     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_contextual_identities.js
17:06:07     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_contextual_identities.js | took 22129ms
17:06:07     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js
17:06:30     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_misc.js | took 22564ms
17:06:30     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_download.js
17:06:52     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_downloads_download.js | took 22359ms
17:06:52     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js
17:07:18  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js | xpcshell return code: 0
Flags: needinfo?(ddurst)
Product: Toolkit → WebExtensions
This bug failed 34 times in the last 7 days. Failing only on windows10-64-ccov, build type is debug.

Recent log:
https://treeherder.mozilla.org/logviewer.html#?job_id=190011529&repo=mozilla-central&lineNumber=2716

TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js
12:04:36  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_storage_telemetry.js | xpcshell return code: 0
12:04:36     INFO -  TEST-INFO took 27658ms

:ddurst:

Can you please take a look at this bug?
Whiteboard: [stockwell needswork]
I've been unable to reproduce this intermittent locally (even by creating a
"win64 ccov debug" build on Windows 10), but it has been easy enough to trigger
on try.

The failure is triggered when the test has been completed and it is unloading the test extension1,
by the `NS_ERROR_FILE_ACCESS_DENIED` error raised from Extension's `cleanupGeneratedFile`
(https://searchfox.org/mozilla-central/rev/f2ac80ab7dbde5400a3400d463e07331194dec94/toolkit/components/extensions/Extension.jsm#1835-1841).

By comparing the test behavior when it runs successfully locally and fails on try, I've been
finally able to identify what goes wrong when it fails:

The reason for the `NS_ERROR_FILE_ACCESS_DENIED` is the ScriptCache entry for the
test extension1's content script, which is created when we create and load the
test content page which triggers it, this script cache entry should be cleared
when the extension shutdown (and it is cleared when the test runs successfully)

Then, right after the content script is executed, the contentPage is closed and this
is where something goes (intermittently) wrong with the ipc (and the following pipe errors
may be related to it: https://treeherder.mozilla.org/logviewer.html#?job_id=194750915&repo=mozilla-central&lineNumber=2692-2702) and, because of that, during the extension shutdown the "Extension:Shutdown" message broadcasted
to all the process never reaches the process where the content script cache entry has been
created (as well as "Extension:FlushJarCache" message sent to ensure that the jar cache is flushed
in every process), and so the XPI file is still kept active by that process and so it fails to be
removed on windows (where the usual `NS_ERROR_FILE_ACCESS_DENIED` is raised in this kind of scenarios).

The underlying issue doesn't seem to be strictly related to the behavior that this test file is
verifying (that is "checking that the expected telemetry data is being collected when the storage
APIs are being used"), and so I think that it would be reasonable to prevent the intermittent
by fixing the test (and closing the page after we unload the test extension 1 is enough to ensure
that the script cache entry is always cleared as expected and the file can be removed successfully
when the test is exiting).

The following push to try seems to confirm it (the oranges are triggered by another unrelated test
which fails intermittently in win64 ccov builds):

- https://treeherder.mozilla.org/#/jobs?repo=try&revision=978e21c57ef084c4115703bf827306320e81bcad
Comment on attachment 9003427 [details]
Bug 1467352 - Fix test_ext_storage_telemetry intermittency on win64-ccov.

Shane Caraveo (:mixedpuppy) has approved the revision.
Attachment #9003427 - Flags: review+
Pushed by luca.greco@alcacoop.it:
https://hg.mozilla.org/integration/autoland/rev/0503d6eb70a7
Fix test_ext_storage_telemetry intermittency on win64-ccov. r=mixedpuppy
Assignee: nobody → lgreco
Status: NEW → ASSIGNED
Flags: needinfo?(ddurst)
https://hg.mozilla.org/mozilla-central/rev/0503d6eb70a7
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
Flags: qe-verify-
You need to log in before you can comment on or make changes to this bug.