Closed Bug 1819278 Opened 2 years ago Closed 1 years ago

Intermittent [TV] TEST-UNEXPECTED-TIMEOUT | remote/marionette/test/xpcshell/test_sync.js | Test timed out

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Platform:
All
Android
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=407239925&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QDxZZU2WQMSODoiu7YLM7Q/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/QDxZZU2WQMSODoiu7YLM7Q/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

INFO -  TEST-PASS | remote/marionette/test/xpcshell/test_sync.js | took 8189ms
[task 2023-02-28T08:33:15.004Z] 08:33:15     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/remote/marionette/test/xpcshell/test_sync.js folder: /data/local/tmp/test_root/xpc/p/ddbb5a61-08ed-4c31-93b2-f9280cb440a8
[task 2023-02-28T08:33:15.208Z] 08:33:15     INFO -  INFO | Result summary:
[task 2023-02-28T08:33:15.208Z] 08:33:15     INFO -  INFO | Passed: 10
[task 2023-02-28T08:33:15.208Z] 08:33:15     INFO -  INFO | Failed: 0
[task 2023-02-28T08:33:15.208Z] 08:33:15     INFO -  INFO | Todo: 0
[task 2023-02-28T08:33:15.208Z] 08:33:15     INFO -  INFO | Retried: 0
[task 2023-02-28T08:33:15.209Z] 08:33:15     INFO -  SUITE-END | took 91s
[task 2023-02-28T08:33:15.210Z] 08:33:15     INFO -  :::
[task 2023-02-28T08:33:15.211Z] 08:33:15     INFO -  ::: Running test verification step "2. Run each test 10 times, sequentially, in chaos mode."...
[task 2023-02-28T08:33:15.211Z] 08:33:15     INFO -  :::
[task 2023-02-28T08:33:15.211Z] 08:33:15     INFO -  Using at most 4 threads.
[task 2023-02-28T08:33:15.211Z] 08:33:15     INFO -  SUITE-START | Running 1 tests
[task 2023-02-28T08:33:15.594Z] 08:33:15     INFO -  TEST-START | remote/marionette/test/xpcshell/test_sync.js
[task 2023-02-28T08:33:15.639Z] 08:33:15     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_DISABLE_CONTENT_SANDBOX=1 --es env6 MOZ_FETCHES_DIR=/builds/worker/fetches --es env7 MOZ_DISABLE_SOCKET_PROCESS=1 --es env8 LD_LIBRARY_PATH=/data/local/tmp/test_root/xpcb --es env9 MOZ_LINKER_CACHE=/data/local/tmp/test_root/xpcb --es env10 GRE_HOME=/data/local/tmp/test_root/xpcb --es env11 XPCSHELL_TEST_PROFILE_DIR=/data/local/tmp/test_root/xpc/p/a9198d3e-856a-462d-8f2a-92614ecf1f79 --es env12 HOME=/data/local/tmp/test_root/xpc/p --es env13 XPCSHELL_TEST_TEMP_DIR=/data/local/tmp/test_root/xpc/tmp/9950683d-04a7-46ec-8e09-9331d43e6bdd --es env14 MOZ_ANDROID_DATA_DIR=/data/local/tmp/test_root/xpcb --es env15 MOZ_IN_AUTOMATION=1 --es env16 MOZ_ANDROID_CPU_ABI=x86_64 --es env17 MOZHTTP2_PORT=34874 --es env18 MOZNODE_EXEC_PORT=34267 --es env19 MOZ_CHAOSMODE=0xfb --es env20 TMPDIR=/data/local/tmp/test_root/xpc/p/a9198d3e-856a-462d-8f2a-92614ecf1f79 --es env21 XPCSHELL_MINIDUMP_DIR=/data/local/tmp/test_root/xpc/minidumps/a9198d3e-856a-462d-8f2a-92614ecf1f79 --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/a9198d3e-856a-462d-8f2a-92614ecf1f79/mozinfo.json";' --es arg9 -e --es arg10 'const _PREFS_FILE = "/data/local/tmp/test_root/xpc/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/remote/marionette/test/xpcshell/head.js"];' --es arg17 -e --es arg18 'const _JSDEBUGGER_PORT = 0;' --es arg19 -e --es arg20 'const _TEST_CWD = "/data/local/tmp/test_root/xpc/remote/marionette/test/xpcshell";' --es arg21 -e --es arg22 'const _TEST_FILE = ["test_sync.js"];' --es arg23 -e --es arg24 'const _TEST_NAME = "remote/marionette/test/xpcshell/test_sync.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-0133acb7-0b88-4b7c-b5f6-36ad3ea1b694.log
[task 2023-02-28T08:33:15.879Z] 08:33:15     INFO -  remotexpcshelltests.py | remote/marionette/test/xpcshell/test_sync.js | 12085 | Launched Test App
[task 2023-02-28T08:38:15.595Z] 08:38:15  WARNING -  TEST-UNEXPECTED-TIMEOUT | remote/marionette/test/xpcshell/test_sync.js | Test timed out
[task 2023-02-28T08:38:15.595Z] 08:38:15     INFO -  TEST-INFO took 300001ms
[task 2023-02-28T08:38:15.613Z] 08:38:15     INFO -  xpcshell return code: -1
[task 2023-02-28T08:38:15.613Z] 08:38:15     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/remote/marionette/test/xpcshell/test_sync.js folder: /data/local/tmp/test_root/xpc/p/a9198d3e-856a-462d-8f2a-92614ecf1f79
[task 2023-02-28T08:40:39.731Z] 08:40:39     INFO -  remotexpcshelltests.py | remote/marionette/test/xpcshell/test_sync.js | 0 | Timing out
[task 2023-02-28T08:40:39.747Z] 08:40:39     INFO -  remotexpcshelltests.py | remote/marionette/test/xpcshell/test_sync.js | 12085 | Application ran for: 0:07:24.152903
[task 2023-02-28T08:40:39.840Z] 08:40:39     INFO -  Cleaning up profile for /builds/worker/workspace/build/tests/xpcshell/tests/remote/marionette/test/xpcshell/test_sync.js folder: /data/local/tmp/test_root/xpc/p/a9198d3e-856a-462d-8f2a-92614ecf1f79
[task 2023-02-28T08:40:40.327Z] 08:40:40     INFO -  TEST-START | remote/marionette/test/xpcshell/test_sync.js

Looks like this is Android only. I've triggered some more jobs to see if this is actually a perma failure:
https://treeherder.mozilla.org/jobs?repo=autoland&revision=2d55d82d13a852aad3d3800af7b21c53eb5edfad&searchStr=tv%2Candroid

It's only the TV jobs that are affected. The xpcshell tests work just fine.

:ofrazy, since you are the author of the regressor, bug 1810101, could you take a look?

For more information, please visit auto_nag documentation.

Flags: needinfo?(ofrazy)
Flags: needinfo?(ofrazy)

I don't think that this is a regression but a problem with TV jobs. Lets wait until the merge to mozilla-central is done and then I can have a look if there is a way to reproduce the problem locally. Right now its intermittently failing.

Keywords: regression
No longer regressed by: 1810101

All the failures happened in step 2. Run each test 10 times, sequentially, in chaos mode.

For me running each individual test takes around 40-60s on my local machine with an emulator. In TaskCluster this same test takes up 197719ms (>3min). In one case it's even 300001ms (5min).

The related test is:
https://searchfox.org/mozilla-central/source/remote/marionette/test/xpcshell/test_sync.js

Joel, do we have hardware which is way slower to run the tests as the emulator?

Flags: needinfo?(jmaher)
OS: Unspecified → Android
Hardware: Unspecified → All

the emulators run on gcp instances; they are slow in general, much faster than they were 6 years ago, compared to any desktop these run much slower.

If the test runs 10x and then times out; I think we need to either:

  1. make the test run faster!
  2. find a way to extend the timeout for this test (ideally in a manifest somewhere or config file)
  3. accept that this fails in test-verify mode

I would be a fan of options 1 or 2. Typically tests will fail in test-verify mode frequently/perma and pass all the time in normal mode.

Flags: needinfo?(jmaher)

Thanks. Given that this only happens for TV jobs when we modify the test it will not have high priority for us right now especially when it works fine for local testing with the emulator.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=419307059&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 2 years ago → 1 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.