Closed Bug 1896262 Opened 6 months ago Closed 5 months ago

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)

defect

Tracking

(firefox-esr115 unaffected, firefox126 unaffected, firefox127 wontfix, firefox128- fixed, firefox129 verified)

VERIFIED FIXED
129 Branch
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)

Central-as-beta-simulation

How to run these simulations

Failure log

[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
Flags: needinfo?(jjalkanen)
Assignee: nobody → jjalkanen
Flags: needinfo?(jjalkanen)

Presumably, this is the same as 1895927

See Also: → 1895927

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.

I've made an early beta simulation today using the patches from Bug 1895927, it seems that they don't fix this issue.

today's beta simulation run

Flags: needinfo?(ehenry)

The regressor changed a test to be async and it is now more important to
handle all the exceptions in the test context.

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:

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

So in short, the test is stuck in the following places:

Flags: needinfo?(ehenry)

The severity field is not set for this bug.
:robwu, could you have a look please?

For more information, please visit BugBot documentation.

Flags: needinfo?(rob)

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?

Severity: -- → S4
Flags: needinfo?(rob)
Priority: -- → P5

@Rob, looking back at yesterday's beta-sim, it seems the frequency is still high/perma

Flags: needinfo?(rob)

(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?

Flags: needinfo?(rob) → needinfo?(jjalkanen)

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).

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.

Flags: needinfo?(jjalkanen)

Any updates on this, Jari? It's still very high-volume.

Flags: needinfo?(jjalkanen)

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.

Flags: needinfo?(jjalkanen)
Flags: needinfo?(jjalkanen)

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).

Attachment #9402188 - Attachment description: Bug 1896262 - Catch errors in cookies behavior test for extensions. r=#extension-reviewers → Bug 1896262 - Increase timeout for test_ext_cookieBehaviors. r=#extension-reviewers,robwu
Flags: needinfo?(jjalkanen)
Keywords: leave-open
See Also: → 1904500

I filed bug 1904500 to address the more general Android performance question.

Pushed by jjalkanen@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/0279d13e7955 Increase timeout for test_ext_cookieBehaviors. r=extension-reviewers,robwu
Status: NEW → RESOLVED
Closed: 5 months ago
Resolution: --- → FIXED
Target Milestone: --- → 129 Branch
Status: RESOLVED → VERIFIED

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 to wontfix.

For more information, please visit BugBot documentation.

Flags: needinfo?(jjalkanen)

test-only change so it does not need a formal uplift request. I can take this in the next beta push.

Flags: needinfo?(jjalkanen)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: