High frequency Android Shippable xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js | Test timed out when Gecko 127 merges to beta on 2024-05-13
Categories
(WebExtensions :: General, defect, P5)
Tracking
(firefox-esr115 unaffected, firefox126 unaffected, firefox127 wontfix, firefox128- fixed, firefox129 verified)
Tracking | Status | |
---|---|---|
firefox-esr115 | --- | unaffected |
firefox126 | --- | unaffected |
firefox127 | --- | wontfix |
firefox128 | - | fixed |
firefox129 | --- | verified |
People
(Reporter: SerbanS, Assigned: jjalkanen)
References
(Regression)
Details
(Keywords: regression)
Attachments
(1 file)
[task 2024-05-11T13:27:17.518Z] 13:27:17 INFO - TEST-PASS | uriloader/exthandler/tests/unit/test_punycodeURIs.js | took 1870ms
[task 2024-05-11T13:27:17.579Z] 13:27:17 INFO - Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/uriloader/exthandler/tests/unit/test_punycodeURIs.js folder: /data/local/tmp/test_root/xpc/p/f655cc42-1091-467c-9142-3e8792b773d4
[task 2024-05-11T13:27:17.742Z] 13:27:17 INFO - Retrying tests that failed when run in parallel.
[task 2024-05-11T13:27:18.137Z] 13:27:18 INFO - TEST-START | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js
[task 2024-05-11T13:27:18.176Z] 13:27:18 INFO - adb launch_application: am startservice -W -n 'org.mozilla.geckoview.test_runner/org.mozilla.geckoview.test_runner.XpcshellTestRunnerService$i0' -a android.intent.action.MAIN --es env0 XPCOM_DEBUG_BREAK=stack-and-abort --es env1 MOZ_CRASHREPORTER=1 --es env2 MOZ_CRASHREPORTER_NO_REPORT=1 --es env3 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es env4 MOZ_DEVELOPER_REPO_DIR=/builds/worker/checkouts/gecko --es env5 MOZ_DEVELOPER_OBJ_DIR=/builds/worker/workspace/obj-build --es env6 MOZ_DISABLE_CONTENT_SANDBOX=1 --es env7 MOZ_FETCHES_DIR=/builds/worker/fetches --es env8 MOZ_DISABLE_SOCKET_PROCESS=1 --es env9 LD_LIBRARY_PATH=/data/local/tmp/test_root/xpcb --es env10 MOZ_LINKER_CACHE=/data/local/tmp/test_root/xpcb --es env11 GRE_HOME=/data/local/tmp/test_root/xpcb --es env12 XPCSHELL_TEST_PROFILE_DIR=/data/local/tmp/test_root/xpc/p/e8bab2ad-7419-4d08-b7c0-c5814cbf7540 --es env13 HOME=/data/local/tmp/test_root/xpc/p --es env14 XPCSHELL_TEST_TEMP_DIR=/data/local/tmp/test_root/xpc/tmp/9555a68b-04d7-4c5a-92c0-7205800401a2 --es env15 MOZ_ANDROID_DATA_DIR=/data/local/tmp/test_root/xpcb --es env16 MOZ_IN_AUTOMATION=1 --es env17 MOZ_ANDROID_CPU_ABI=x86_64 --es env18 MOZHTTP2_PORT=43509 --es env19 MOZNODE_EXEC_PORT=36092 --es env20 MOZHTTP3_ECH= --es env21 TMPDIR=/data/local/tmp/test_root/xpc/p/e8bab2ad-7419-4d08-b7c0-c5814cbf7540 --es env22 XPCSHELL_MINIDUMP_DIR=/data/local/tmp/test_root/xpc/minidumps/e8bab2ad-7419-4d08-b7c0-c5814cbf7540 --es arg0 -g --es arg1 /data/local/tmp/test_root/xpcb --es arg2 --greomni --es arg3 /data/local/tmp/test_root/xpcb/geckoview-test_runner.apk --es arg4 -m --es arg5 -e --es arg6 'const _HEAD_JS_PATH = "/data/local/tmp/test_root/xpc/head.js";' --es arg7 -e --es arg8 'const _MOZINFO_JS_PATH = "/data/local/tmp/test_root/xpc/p/e8bab2ad-7419-4d08-b7c0-c5814cbf7540/mozinfo.json";' --es arg9 -e --es arg10 'const _PREFS_FILE = "/data/local/tmp/test_root/xpc/tmp/9555a68b-04d7-4c5a-92c0-7205800401a2/user.js";' --es arg11 -e --es arg12 'const _TESTING_MODULES_DIR = "/data/local/tmp/test_root/xpc/m";' --es arg13 -f --es arg14 /data/local/tmp/test_root/xpc/head.js --es arg15 -e --es arg16 'const _HEAD_FILES = ["/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_telemetry.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_sync.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_storage.js"];' --es arg17 -e --es arg18 'const _JSDEBUGGER_PORT = 0;' --es arg19 -e --es arg20 'const _TEST_CWD = "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell";' --es arg21 -e --es arg22 'const _TEST_FILE = ["test_ext_cookieBehaviors.js"];' --es arg23 -e --es arg24 'const _TEST_NAME = "xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js";' --es arg25 -e --es arg26 '_execute_test(); quit(0);' --ez use_multiprocess True --es out_file /data/local/tmp/test_root/xpc/logs/xpcshell-fb1cc730-4646-425b-a1ad-cedb15c7a278.log
[task 2024-05-11T13:27:18.381Z] 13:27:18 INFO - remotexpcshelltests.py | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js | 21257 | Launched Test App
[task 2024-05-11T13:32:18.138Z] 13:32:18 WARNING - TEST-UNEXPECTED-TIMEOUT | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js | Test timed out
[task 2024-05-11T13:32:18.138Z] 13:32:18 INFO - TEST-INFO took 300000ms
[task 2024-05-11T13:32:18.154Z] 13:32:18 INFO - xpcshell return code: -1
[task 2024-05-11T13:32:18.154Z] 13:32:18 INFO - Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js folder: /data/local/tmp/test_root/xpc/p/e8bab2ad-7419-4d08-b7c0-c5814cbf7540
[task 2024-05-11T13:34:42.357Z] 13:34:42 INFO - remotexpcshelltests.py | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js | 0 | Timing out
[task 2024-05-11T13:34:42.369Z] 13:34:42 INFO - remotexpcshelltests.py | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js | 21257 | Application ran for: 0:07:24.231605
[task 2024-05-11T13:34:42.434Z] 13:34:42 INFO - Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js folder: /data/local/tmp/test_root/xpc/p/e8bab2ad-7419-4d08-b7c0-c5814cbf7540
[task 2024-05-11T13:34:42.543Z] 13:34:42 INFO - TEST-START | netwerk/test/unit_ipc/test_http3_prio_disabled_wrap.js
Assignee | ||
Updated•6 months ago
|
Comment 2•6 months ago
|
||
Looks like a fix is coming in bug 1895927 so when/if that fixes this error we should be able to close this as a duplicate.
Comment 3•6 months ago
|
||
I've made an early beta simulation today using the patches from Bug 1895927, it seems that they don't fix this issue.
Updated•6 months ago
|
Assignee | ||
Comment 4•6 months ago
|
||
The regressor changed a test to be async and it is now more important to
handle all the exceptions in the test context.
Comment 5•6 months ago
•
|
||
This is a rather long comment, it includes tips on viewing logs, an excerpt of the relevant log, an analysis of the log and finally the place where the test gets stuck. I hope that this helps!
Tips on debugging, how to view the relevant logs:
- In comment 3, click on the treeherder link to view the job that failed. Then click on the "Artifacts and Debugging Tools" tab (next to "Failure Summary").
- Download the linked logcat file,
logcat-emulator-5554.log
(https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BxiyYBQtTW6Q7BfDQlHmfA/runs/0/artifacts/public/test_info/logcat-emulator-5554.log) - Due to bug 1844829 there is logspam, filter it: https://bugzilla.mozilla.org/show_bug.cgi?id=1844829#c5
- If you're debugging locally, use
adb logcat | grep ...
as shown in the report at bug 1844829.
- If you're debugging locally, use
Here is the relevant excerpt from the log file after following the above steps:
05-15 15:15:59.436 21840 21861 I Gecko : {"action":"log","time":1715786159436,"thread":null,"pid":null,"source":"xpcshell/head.js","level":"INFO","message":"\"Test extension page access to indexedDB & localStorage with BEHAVIOR_LIMIT_FOREIGN\""}
...
05-15 15:15:59.760 21840 21861 I Gecko : {"action":"log","time":1715786159760,"thread":null,"pid":null,"source":"xpcshell/head.js","level":"INFO","message":"\"Test from a top level extension page\""}
05-15 15:15:59.884 21840 21861 I Gecko :
05-15 15:15:59.884 21840 21861 I Gecko : {"action":"test_status","time":1715786159884,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 157] Just created database should be found - true == true"
... ( omitted some non-Gecko logs - note the 5 minute gap!) ...
05-15 15:21:05.024 21840 21861 I Gecko : {"action":"log","time":1715786465024,"thread":null,"pid":null,"source":"xpcshell/head.js","level":"INFO","message":"\"IndexedDB is accessible\""}
05-15 15:21:05.031 21840 21861 I Gecko :
05-15 15:21:05.031 21840 21861 I Gecko : {"action":"test_status","time":1715786465031,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 157] localStorage global should be defined - true == true"}
05-15 15:21:05.031 21840 21861 I Gecko :
05-15 15:21:05.031 21840 21861 I Gecko : {"action":"test_status","time":1715786465031,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 157] localStorage global should be defined - true == true"}
05-15 15:21:10.117 21840 21861 I Gecko :
05-15 15:21:10.117 21840 21861 I Gecko : {"action":"test_status","time":1715786470115,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 157] extension page worker have access to indexedDB - true == true"}
05-15 15:21:10.120 21840 21861 I Gecko :
05-15 15:21:10.120 21840 21861 I Gecko : {"action":"test_status","time":1715786470120,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 216] Got the results from the expected url - \"moz-extension://f37fbd0c-fa74-4b05-92b0-191107b28672/page.html\" == \"moz-extension://f37fbd0c-fa74-4b05-92b0-191107b28672/page.html\""}
05-15 15:21:10.120 21840 21861 I Gecko :
05-15 15:21:10.120 21840 21861 I Gecko : {"action":"log","time":1715786470120,"thread":null,"pid":null,"source":"xpcshell/head.js","level":"INFO","message":"\"Test from a sub frame extension page\""}
05-15 15:21:10.274 21840 21861 I Gecko :
05-15 15:21:10.274 21840 21861 I Gecko : {"action":"test_status","time":1715786470274,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 157] Just created database should be found - true == true"}
05-15 15:21:18.326 21840 21861 I Gecko :
05-15 15:21:18.326 21840 21861 I Gecko : {"action":"log","time":1715786478326,"thread":null,"pid":null,"source":"xpcshell/head.js","level":"INFO","message":"\"IndexedDB is accessible\""}
05-15 15:21:18.331 21840 21861 I Gecko :
05-15 15:21:18.331 21840 21861 I Gecko : {"action":"test_status","time":1715786478331,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 157] localStorage global should be defined - true == true"}
05-15 15:21:23.415 21840 21861 I Gecko :
05-15 15:21:23.415 21840 21861 I Gecko : {"action":"test_status","time":1715786483415,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 157] extension page worker have access to indexedDB - true == true"}
05-15 15:21:23.420 21840 21861 I Gecko :
05-15 15:21:23.420 21840 21861 I Gecko : {"action":"test_status","time":1715786483420,"thread":null,"pid":null,"source":"xpcshell/head.js","test":"xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js","subtest":"test_ext_page_allowed_storage","status":"PASS","message":"[test_ext_page_allowed_storage : 226] Got the results from the expected url - \"moz-extension://f37fbd0c-fa74-4b05-92b0-191107b28672/page_subframe.html\" == \"moz-extension://f37fbd0c-fa74-4b05-92b0-191107b28672/page_subframe.html\""}
05-15 15:21:23.481 21840 21861 E GeckoConsole: [JavaScript Error: "[Exception... "Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIFile.remove]" nsresult: "0x80520012 (NS_ERROR_FILE_NOT_FOUND)" location: "JS frame :: resource://gre/modules/Extension.sys.mjs :: cleanupGeneratedFile/< :: line 3798" data: no]"]
I annotated some lines inline. The one thing that stands out is that the test gets stuck at some point, but unstuck after 5 minutes. I suspect that the "getting unstuck" part is that the internals detect a profile directory change and resume execution somehow. The profile directory changes because a test times out after 5 minutes, after which the temporary test artifacts (including profile directory and temp dir) are erased. The last part of the log shows that clearly: the generated test extension cannot be removed, because it was already removed.
The last successful message before the test gets stuck is [test_ext_page_allowed_storage : 157] Just created database should be found - true == true
, meaning:
- test task is
test_ext_page_allowed_storage
- assertion message was
Just created database should be found
The only message in the test task that satisfies that is at https://searchfox.org/mozilla-central/rev/445a6e86233c733c5557ef44e1d33444adaddefc/toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js#77-81
- The
testWebStorages
function is serialized and referenced throughtest_web_storages.js
(source), which is loaded through multiple test pages (page.html
(source) andpage_subframe.html
which is loaded viapage_with_subframe.html
). - If I look at the penultimate log message, it is "Test from a top level extension page", which is means that the only place that it could have been called at https://searchfox.org/mozilla-central/rev/445a6e86233c733c5557ef44e1d33444adaddefc/toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js#212-213
- That specific logic is run in a loop, but if I look back a few lines I can infer that the issue happens at the first iteration of the loop (relevant source).
So in short, the test is stuck in the following places:
- Waiting for
test-storage:done
at https://searchfox.org/mozilla-central/rev/445a6e86233c733c5557ef44e1d33444adaddefc/toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js#212-215 test-storage:done
is waiting for completion ofindexedDB.deleteDatabase("door").onsuccess
after
https://searchfox.org/mozilla-central/rev/445a6e86233c733c5557ef44e1d33444adaddefc/toolkit/components/extensions/test/xpcshell/test_ext_cookieBehaviors.js#77-81- after the "Just created database should be found" message, the next expected log is "IndexedDB is accessible". In between, the only async operation is
indexedDB.deleteDatabase("door")
. - Note that when the test times out, "IndexedDB is accessible" is logged, which shows that something caused
deleteDatabase
to finally complete and trigger theonsuccess
event.
- after the "Just created database should be found" message, the next expected log is "IndexedDB is accessible". In between, the only async operation is
Updated•6 months ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•6 months ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 8•6 months ago
|
||
The severity field is not set for this bug.
:robwu, could you have a look please?
For more information, please visit BugBot documentation.
Comment 9•6 months ago
|
||
The title states high frequency but 5 failures in the past week doesn't seem that bad. In fact, the last one was 5 days ago. Is the frequency of beta sims low, or was the issue fixed by something else?
Comment 10•6 months ago
|
||
@Rob, looking back at yesterday's beta-sim, it seems the frequency is still high/perma
Comment 11•6 months ago
|
||
(In reply to Sandor Molnar[:smolnar] from comment #10)
@Rob, looking back at yesterday's beta-sim, it seems the frequency is still high/perma
I looked at this log, and it is equivalent to the logs I analyzed before. For the analysis, see https://bugzilla.mozilla.org/show_bug.cgi?id=1896262#c5
The root cause is in IndexedDB. As mentioned in comment 5, the test is stuck for several minutes at indexedDB.deleteDatabase()
, and onsuccess
is only invoked when an external process has wiped the entire profile directory (due to tests being cleaned up after 5 minutes).
Jari - could you look into this, or find someone who can?
Comment 12•6 months ago
|
||
The beta-sim try push above only listed opt builds. I manually triggered some debug jobs by scheduling jobs with the Treeherder UI: (triangle -> Add jobs -> select the X[all] and X-nofis-ship[all] tasks of the "Android 7.0 x86-64 WebRender debug" and "Android 7.0 x86-64 WebRender debug-isolated-process").
Hopefully it lists some useful debugging information (see comment 5 to learn how to download and filter the log for readability).
Assignee | ||
Comment 13•6 months ago
|
||
Thank you for the careful log analysis exemplification! I am probably the most available person to look into this, and also it was my change that uncovered this problem.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 16•5 months ago
|
||
Any updates on this, Jari? It's still very high-volume.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 18•5 months ago
|
||
On a normal run, the test now takes around three and a half minutes, which is not that far from the timeout limit 5 min. In general, IDB seems to be many times slower on Android and it is fathomable that it's the deleteDatabase call that is hanging here.
Assignee | ||
Updated•5 months ago
|
Comment 19•5 months ago
|
||
A delay of several minutes for database deletion seems excessive and worth a bug on its own.
If offering more time to the test resolves the test timeout, request more time by adding requesttimeoutfactor = 2
to the test manifest (or whatever reasonable time multiplier is needed).
Comment hidden (Intermittent Failures Robot) |
Updated•5 months ago
|
Assignee | ||
Updated•5 months ago
|
Assignee | ||
Comment 21•5 months ago
|
||
I filed bug 1904500 to address the more general Android performance question.
Comment 22•5 months ago
|
||
Updated•5 months ago
|
Comment 23•5 months ago
|
||
bugherder |
Comment 24•5 months ago
|
||
The patch is working in today's beta-simulation: https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&revision=8032811e0d6088e1cb10513b68d8b8833c4f2688&searchStr=android%2Cxpcshell
Updated•5 months ago
|
Updated•5 months ago
|
Updated•5 months ago
|
Comment 25•5 months ago
|
||
The patch landed in nightly and beta is affected.
:jjalkanen, is this bug important enough to require an uplift?
- If yes, please nominate the patch for beta approval.
- If no, please set
status-firefox128
towontfix
.
For more information, please visit BugBot documentation.
Comment 26•5 months ago
|
||
test-only change so it does not need a formal uplift request. I can take this in the next beta push.
Comment 27•5 months ago
|
||
uplift |
Updated•5 months ago
|
Comment hidden (Intermittent Failures Robot) |
Description
•