1851318 - Intermittent TV-nofis TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js | Test timed out

Status: NEW

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=427803199&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dqm1Y3rvTZGhKzEtsgNy9Q/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dqm1Y3rvTZGhKzEtsgNy9Q/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2023-09-02T12:19:31.028Z] 12:19:31     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js
[task 2023-09-02T12:19:31.070Z] 12:19:31     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/172bf691-e75d-44d1-a984-16a81dc95489 --es env13 HOME=/data/local/tmp/test_root/xpc/p --es env14 XPCSHELL_TEST_TEMP_DIR=/data/local/tmp/test_root/xpc/tmp/597d13b7-3889-4983-8dd4-8dbccf1552b7 --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=46107 --es env19 MOZNODE_EXEC_PORT=42085 --es env20 MOZHTTP3_ECH= --es env21 MOZ_CHAOSMODE=0xfb --es env22 TMPDIR=/data/local/tmp/test_root/xpc/p/172bf691-e75d-44d1-a984-16a81dc95489 --es env23 XPCSHELL_MINIDUMP_DIR=/data/local/tmp/test_root/xpc/minidumps/172bf691-e75d-44d1-a984-16a81dc95489 --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/172bf691-e75d-44d1-a984-16a81dc95489/mozinfo.json";' --es arg9 -e --es arg10 'const _PREFS_FILE = "/data/local/tmp/test_root/xpc/tmp/597d13b7-3889-4983-8dd4-8dbccf1552b7/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_remote.js", "/data/local/tmp/test_root/xpc/toolkit/components/extensions/test/xpcshell/head_e10s.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_persistent_events.js"];' --es arg23 -e --es arg24 'const _TEST_NAME = "xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.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-6ea9eeb0-8406-4c37-8495-b4c46b5735cc.log
[task 2023-09-02T12:19:31.303Z] 12:19:31     INFO -  remotexpcshelltests.py | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js | 8267 | Launched Test App
[task 2023-09-02T12:24:31.029Z] 12:24:31  WARNING -  TEST-UNEXPECTED-TIMEOUT | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js | Test timed out
[task 2023-09-02T12:24:31.029Z] 12:24:31     INFO -  TEST-INFO took 300000ms
[task 2023-09-02T12:24:31.044Z] 12:24:31     INFO -  xpcshell return code: -1
[task 2023-09-02T12:24:31.044Z] 12:24:31     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js folder: /data/local/tmp/test_root/xpc/p/172bf691-e75d-44d1-a984-16a81dc95489
[task 2023-09-02T12:26:55.197Z] 12:26:55     INFO -  remotexpcshelltests.py | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js | 8267 | Timing out
[task 2023-09-02T12:27:00.264Z] 12:27:00     INFO -  remotexpcshelltests.py | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js | 8267 | Application ran for: 0:07:29.234950
[task 2023-09-02T12:27:00.338Z] 12:27:00     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js folder: /data/local/tmp/test_root/xpc/p/172bf691-e75d-44d1-a984-16a81dc95489
[task 2023-09-02T12:27:00.868Z] 12:27:00     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_ext_persistent_events.js

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

:rpl, since you are the author of the regressor, bug 1848020, could you take a look?

For more information, please visit BugBot documentation.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1848020

Comment 3

[Intermittent Failures Robot]

2 failures in 3019 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 1
  • opt: 1
• android-em-7-0-x86_64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1851318&startday=2023-08-28&endday=2023-09-03&tree=all

Comment 4

[Luca Greco [:rpl] [:luca] [:lgreco]]

I took a look into this TV job failure:

• the test task hitting the failure is the one named test_persistent_events, and it is failing with a timeout when the call to localStorage.getItem at the start of the background script throws an NS_ERROR_ABORT and so the rest of the background script isn't going to be executed, e.g. see the errors logged as the following one visible in the adb logcat output attached to the failure:

09-02 12:23:33.143  8324  8339 E WebExtensions: [JavaScript Error: "NS_ERROR_ABORT: " {file: "moz-extension://ce3f8cf4-7365-42a8-9ea2-5e0c73a945ca/%7B571a8f82-e9d7-41a0-8260-be18c09cfc8d%7D.js" line: 4}]
09-02 12:23:33.143  8324  8339 E WebExtensions: background@moz-extension://ce3f8cf4-7365-42a8-9ea2-5e0c73a945ca/%7B571a8f82-e9d7-41a0-8260-be18c09cfc8d%7D.js:4:24
09-02 12:23:33.143  8324  8339 E WebExtensions: @moz-extension://ce3f8cf4-7365-42a8-9ea2-5e0c73a945ca/%7B571a8f82-e9d7-41a0-8260-be18c09cfc8d%7D.js:34:7

• the test task that is currently hitting a failure is NOT the test task that has been tweaked from Bug 1848020
• I don't yet see how the changes landed from Bug 1848020 could be triggering this issue, and so I don't exclude that the only relationship with Bug 1848020 patch is that we had to include a small tweak on the other test task part of this file (which then triggered the TV job to be executed)
• I can reproduce this locally too, the issue is hit on the first run in chaos mode

I have to dig a bit more to determine what is making us hitting the NS_ERROR_ABORT from the call to localStorage.getItem, at a first glance it seems we may be intermittently be failing to preload the localStorage data (which is expected to be synchronously propagated aver IPC) but I don't have enough details yet to determine what may be the underlying reason why we are hitting that in chaos mode.

Comment 5

[Intermittent Failures Robot]

15 failures in 3267 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 15

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 12
  • debug: 4
  • opt: 5
  • debug-isolated-process: 3
• android-em-7-0-x86_64-lite-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1851318&startday=2023-09-04&endday=2023-09-10&tree=all

Comment 6

[Intermittent Failures Robot]

3 failures in 3952 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 2
  • debug-isolated-process: 1
  • opt: 1
• android-em-7-0-x86_64-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1851318&startday=2024-01-29&endday=2024-02-04&tree=all

Comment 7

[Intermittent Failures Robot]

4 failures in 4202 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 3
  • debug-isolated-process: 1
  • debug: 1
  • opt: 1
• android-em-7-0-x86_64-lite-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1851318&startday=2024-05-27&endday=2024-06-02&tree=all