Open Bug 1933914 Opened 13 days ago Updated 9 days ago

Intermittent xpc Automation Error: mozharness timed out after 1000 seconds running ['D:\\task_173278106575060\\build\\venv\\Scripts\\python', '-u', 'D:\\task_173278106575060\\build\\tests\\xpcshell\\runxpcshelltests.py', 'browser/comp| single tracking bug

Categories

(Testing :: XPCShell Harness, defect, P5)

defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned, NeedInfo)

References

(Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression)

Filed by: amarc [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=484519843&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eCywQTkfSBCkflrIq69UHA/runs/0/artifacts/public/logs/live_backing.log


[task 2024-11-28T08:25:05.316Z] 08:25:05     INFO -  These variables are available in the mozinfo environment and can be used to skip tests conditionally:
[task 2024-11-28T08:25:05.318Z] 08:25:05     INFO -      appname: firefox
[task 2024-11-28T08:25:05.318Z] 08:25:05     INFO -      artifact: False
[task 2024-11-28T08:25:05.318Z] 08:25:05     INFO -      asan: False
[task 2024-11-28T08:25:05.318Z] 08:25:05     INFO -      automation: True
[task 2024-11-28T08:25:05.318Z] 08:25:05     INFO -      bin_suffix: .exe
[task 2024-11-28T08:25:05.319Z] 08:25:05     INFO -      bits: 32
[task 2024-11-28T08:25:05.319Z] 08:25:05     INFO -      buildapp: browser
[task 2024-11-28T08:25:05.319Z] 08:25:05     INFO -      buildtype: pgo
[task 2024-11-28T08:25:05.319Z] 08:25:05     INFO -      buildtype_guess: pgo
[task 2024-11-28T08:25:05.319Z] 08:25:05     INFO -      cc_type: clang-cl
[task 2024-11-28T08:25:05.320Z] 08:25:05     INFO -      ccov: False
[task 2024-11-28T08:25:05.320Z] 08:25:05     INFO -      condprof: False
[task 2024-11-28T08:25:05.320Z] 08:25:05     INFO -      crashreporter: True
[task 2024-11-28T08:25:05.320Z] 08:25:05     INFO -      datareporting: True
[task 2024-11-28T08:25:05.320Z] 08:25:05     INFO -      debug: False
[task 2024-11-28T08:25:05.320Z] 08:25:05     INFO -      devedition: False
[task 2024-11-28T08:25:05.321Z] 08:25:05     INFO -      domstreams: True
[task 2024-11-28T08:25:05.321Z] 08:25:05     INFO -      e10s: False
[task 2024-11-28T08:25:05.321Z] 08:25:05     INFO -      early_beta_or_earlier: True
[task 2024-11-28T08:25:05.321Z] 08:25:05     INFO -      fission: True
[task 2024-11-28T08:25:05.321Z] 08:25:05     INFO -      gecko_profiler: True
[task 2024-11-28T08:25:05.321Z] 08:25:05     INFO -      healthreport: True
[task 2024-11-28T08:25:05.322Z] 08:25:05     INFO -      is_ubuntu: False
[task 2024-11-28T08:25:05.322Z] 08:25:05     INFO -      isolated_process: False
[task 2024-11-28T08:25:05.322Z] 08:25:05     INFO -      mozconfig: /builds/worker/checkouts/gecko/.mozconfig
[task 2024-11-28T08:25:05.323Z] 08:25:05     INFO -      msix: False
[task 2024-11-28T08:25:05.323Z] 08:25:05     INFO -      nightly_build: True
[task 2024-11-28T08:25:05.323Z] 08:25:05     INFO -      normandy: True
[task 2024-11-28T08:25:05.323Z] 08:25:05     INFO -      official: True
[task 2024-11-28T08:25:05.323Z] 08:25:05     INFO -      opt: True
[task 2024-11-28T08:25:05.324Z] 08:25:05     INFO -      os: win
[task 2024-11-28T08:25:05.324Z] 08:25:05     INFO -      pgo: True
[task 2024-11-28T08:25:05.324Z] 08:25:05     INFO -      platform_guess: win32
[task 2024-11-28T08:25:05.324Z] 08:25:05     INFO -      processor: x86
[task 2024-11-28T08:25:05.324Z] 08:25:05     INFO -      release_or_beta: False
[task 2024-11-28T08:25:05.324Z] 08:25:05     INFO -      require_signing: False
[task 2024-11-28T08:25:05.325Z] 08:25:05     INFO -      sessionHistoryInParent: True
[task 2024-11-28T08:25:05.325Z] 08:25:05     INFO -      socketprocess_networking: True
[task 2024-11-28T08:25:05.325Z] 08:25:05     INFO -      stylo: True
[task 2024-11-28T08:25:05.325Z] 08:25:05     INFO -      sync: True
[task 2024-11-28T08:25:05.325Z] 08:25:05     INFO -      telemetry: False
[task 2024-11-28T08:25:05.326Z] 08:25:05     INFO -      tests_enabled: True
[task 2024-11-28T08:25:05.326Z] 08:25:05     INFO -      toolkit: windows
[task 2024-11-28T08:25:05.326Z] 08:25:05     INFO -      topobjdir: /builds/worker/workspace/obj-build
[task 2024-11-28T08:25:05.326Z] 08:25:05     INFO -      topsrcdir: /builds/worker/checkouts/gecko
[task 2024-11-28T08:25:05.326Z] 08:25:05     INFO -      tsan: False
[task 2024-11-28T08:25:05.327Z] 08:25:05     INFO -      ubsan: False
[task 2024-11-28T08:25:05.327Z] 08:25:05     INFO -      updater: True
[task 2024-11-28T08:25:05.327Z] 08:25:05     INFO -      verify: False
[task 2024-11-28T08:25:05.347Z] 08:25:05     INFO -  testAddTaskRunNextTest (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskRunNextTest)
[task 2024-11-28T08:25:06.130Z] 08:25:06     INFO -  Calling run_next_test() from inside add_task() results in failure. ... ok
[task 2024-11-28T08:25:06.598Z] 08:25:06     INFO -  testAddTaskSkip (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskSkip) ... ok
[task 2024-11-28T08:25:07.060Z] 08:25:07     INFO -  testAddTaskSkipAll (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskSkipAll) ... ok
[task 2024-11-28T08:25:07.062Z] 08:25:07     INFO -  testAddTaskStackTrace (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskStackTrace)
[task 2024-11-28T08:25:07.700Z] 08:25:07     INFO -  Ensuring that calling Assert.ok(false) from inside add_task() ... ok
[task 2024-11-28T08:25:07.702Z] 08:25:07     INFO -  testAddTaskTestFailureInside (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskTestFailureInside)
[task 2024-11-28T08:25:08.310Z] 08:25:08     INFO -  Ensure tests inside task are reported as failures. ... ok
[task 2024-11-28T08:25:08.311Z] 08:25:08     INFO -  testAddTaskTestMultiple (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskTestMultiple)
[task 2024-11-28T08:25:08.767Z] 08:25:08     INFO -  Ensure multiple calls to add_test_task() work as expected. ... ok
[task 2024-11-28T08:25:08.768Z] 08:25:08     INFO -  testAddTaskTestRejected (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskTestRejected)
[task 2024-11-28T08:25:09.376Z] 08:25:09     INFO -  Ensure rejected task reports as failure. ... ok
[task 2024-11-28T08:25:09.378Z] 08:25:09     INFO -  testAddTaskTestRejectedUndefined (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskTestRejectedUndefined)
[task 2024-11-28T08:25:10.010Z] 08:25:10     INFO -  Ensure rejected task with undefined reason reports as failure and does not hang. ... ok
[task 2024-11-28T08:25:10.011Z] 08:25:10     INFO -  testAddTaskTestSingle (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTaskTestSingle)
[task 2024-11-28T08:25:10.451Z] 08:25:10     INFO -  Ensure add_test_task() with a single passing test works. ... ok
[task 2024-11-28T08:25:10.452Z] 08:25:10     INFO -  testAddTestFailing (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTestFailing)
[task 2024-11-28T08:25:11.065Z] 08:25:11     INFO -  Ensure add_test() with a failing test is reported. ... ok
[task 2024-11-28T08:25:11.067Z] 08:25:11     INFO -  testAddTestSimple (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTestSimple)
[task 2024-11-28T08:25:11.513Z] 08:25:11     INFO -  Ensure simple add_test() works. ... ok
[task 2024-11-28T08:25:11.514Z] 08:25:11     INFO -  testAddTestUncaughtRejection (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAddTestUncaughtRejection)
[task 2024-11-28T08:25:12.131Z] 08:25:12     INFO -  Ensure add_test() with an uncaught rejection is reported. ... ok
[task 2024-11-28T08:25:12.133Z] 08:25:12     INFO -  testAssertStack (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAssertStack)
[task 2024-11-28T08:25:12.133Z] 08:25:12     INFO -  When an assertion is hit, we should produce a useful stack. ... skipped "We don't have a stack fixer on hand for windows."
[task 2024-11-28T08:25:12.133Z] 08:25:12     INFO -  testAsyncCleanup (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testAsyncCleanup)
[task 2024-11-28T08:25:12.742Z] 08:25:12     INFO -  Check that registerCleanupFunction handles nicely async cleanup tasks ... ok
[task 2024-11-28T08:25:12.744Z] 08:25:12     INFO -  testChild (__main__.XPCShellTests.runSelfTest.<locals>.XPCShellTestsTests.testChild)
[task 2024-11-28T08:25:42.965Z] 08:25:42     INFO -  Checks that calling do_load_child_test_harness without run_test_in_child ... Error 0x1 in MiniDumpWriteDump
[task 2024-11-28T08:42:22.977Z] 08:42:22     INFO - Automation Error: mozharness timed out after 1000 seconds running ['D:\\task_173278106575060\\build\\venv\\Scripts\\python', '-u', 'D:\\task_173278106575060\\build\\tests\\xpcshell\\runxpcshelltests.py', 'browser/components/aboutwelcome/tests/xpcshell/xpcshell.toml', 'browser/components/customizableui/test/unit/xpcshell.toml', 'browser/components/extensions/test/xpcshell/xpcshell.toml', 'browser/components/newtab/test/xpcshell/xpcshell.toml', 'browser/components/search/test/unit/xpcshell.toml', 'browser/components/topsites/test/unit/xpcshell.toml', 'browser/modules/test/unit/xpcshell.toml', 'chrome/test/unit_ipc/xpcshell.toml', 'devtools/client/framework/test/xpcshell/xpcshell.toml', 'devtools/client/memory/test/xpcshell/xpcshell.toml', 'devtools/client/shared/redux/middleware/test/xpcshell/xpcshell.toml', 'devtools/platform/tests/xpcshell/xpcshell.toml', 'devtools/shared/discovery/tests/xpcshell/xpcshell.toml', 'devtools/shared/qrcode/tests/xpcshell/xpcshell.toml', 'devtools/shared/transport/tests/xpcshell/xpcshell.toml', 'dom/abort/tests/unit/xpcshell.toml', 'dom/encoding/test/unit/xpcshell.toml', 'dom/indexedDB/test/unit/xpcshell-parent-process.toml', 'dom/messagechannel/tests/unit/xpcshell.toml', 'dom/push/test/xpcshell/xpcshell.toml', 'dom/quota/test/xpcshell/xpcshell.toml', 'dom/tests/unit/xpcshell.toml', 'extensions/spellcheck/hunspell/tests/unit/xpcshell.toml', 'intl/strres/tests/unit/xpcshell.toml', 'layout/tools/layout-debug/tests/unit/xpcshell.toml', 'modules/libmar/tests/unit/xpcshell.toml', 'netwerk/dns/tests/unit/xpcshell.toml', 'parser/xml/test/unit/xpcshell.toml', 'remote/shared/test/xpcshell/xpcshell.toml', 'security/manager/ssl/tests/unit/xpcshell.toml', 'services/settings/test/unit/xpcshell.toml', 'testing/modules/tests/xpcshell/xpcshell.toml', 'toolkit/components/aboutthirdparty/tests/xpcshell/xpcshell.toml', 'toolkit/components/autocomplete/tests/unit/xpcshell.toml', 'toolkit/components/cascade_bloom_filter/test/xpcshell/xpcshell.toml', 'toolkit/components/commandlines/test/unit_win/xpcshell.toml', 'toolkit/components/cookiebanners/test/unit/xpcshell.toml', 'toolkit/components/ctypes/tests/unit/xpcshell.toml', 'toolkit/components/extensions/test/xpcshell/webidl-api/xpcshell.toml', 'toolkit/components/featuregates/test/unit/xpcshell.toml', 'toolkit/components/mediasniffer/test/unit/xpcshell.toml', 'toolkit/components/normandy/test/unit/xpcshell.toml', 'toolkit/components/places/tests/favicons/xpcshell.toml', 'toolkit/components/places/tests/migration/xpcshell.toml', 'toolkit/components/processtools/tests/xpcshell/xpcshell.toml', 'toolkit/components/satchel/test/unit/xpcshell.toml', 'toolkit/components/startup/tests/unit/xpcshell.toml', 'toolkit/components/terminator/tests/xpcshell/xpcshell.toml', 'toolkit/components/uniffi-bindgen-gecko-js/fixtures/tests/xpcshell/xpcshell.toml', 'toolkit/components/windowcreator/tests/unit/xpcshell.toml', 'toolkit/crashreporter/test/unit/xpcshell.toml', 'toolkit/modules/tests/xpcshell/xpcshell.toml', 'toolkit/mozapps/extensions/test/xpcshell/xpcshell-unpack.toml', 'toolkit/mozapps/update/tests/unit_base_updater/xpcshell.toml', 'tools/code-coverage/tests/xpcshell/xpcshell.toml', 'widget/tests/unit/xpcshell.toml', '--threads', '2', '--setpref=layout.css.stylo-threads=4', '--setpref=network.process.enabled=true', '--setpref=network.http.network_access_on_socket_process.enabled=true', '--setpref=layers.d3d11.enable-blacklist=false', '--self-test', '--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Zz8D-3tiT7WltbK4VRa0YA/artifacts/public/build/target.crashreporter-symbols.zip', '--log-errorsummary=D:\\task_173278106575060\\build\\blobber_upload_dir\\xpcshell_errorsummary.log', '--utility-path=tests/bin', '--manifest=tests/xpcshell/tests/xpcshell.toml', '--xpcshell=D:\\task_173278106575060\\build\\application\\firefox/xpcshell.exe', '--msix-app-binary=D:\\task_173278106575060\\build\\application\\firefox\\firefox.exe', '--msix-app-path=D:\\task_173278106575060\\build\\application\\firefox', '--msix-xre-path=D:\\task_173278106575060\\build\\application\\firefox']
[task 2024-11-28T08:42:22.979Z] 08:42:22     INFO - Return code: 1
[task 2024-11-28T08:42:22.979Z] 08:42:22    ERROR - No tests run or test summary not found
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - TinderboxPrint: xpcshell-xpcshell<br/><em class="testfail">T-FAIL</em>
[task 2024-11-28T08:42:22.980Z] 08:42:22  WARNING - setting return code to 2
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - Running post-action listener: _package_coverage_data
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - Running post-action listener: _resource_record_post_action
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - Running post-action listener: process_java_coverage_data
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - [mozharness: 2024-11-28 08:42:22.980848Z] Finished run-tests step (success)
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - [mozharness: 2024-11-28 08:42:22.980848Z] Running uninstall step.
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - Running pre-action listener: _resource_record_pre_action
[task 2024-11-28T08:42:22.980Z] 08:42:22     INFO - Running main action method: uninstall
[task 2024-11-28T08:42:22.981Z] 08:42:22     INFO - Skipping uninstall for non-MSIX test
[task 2024-11-28T08:42:22.981Z] 08:42:22     INFO - Running post-action listener: _resource_record_post_action
[task 2024-11-28T08:42:22.981Z] 08:42:22     INFO - [mozharness: 2024-11-28 08:42:22.981381Z] Finished uninstall step (success)
[task 2024-11-28T08:42:22.981Z] 08:42:22     INFO - Running post-run listener: _resource_record_post_run
[task 2024-11-28T08:42:23.727Z] 08:42:23     INFO - Validating Perfherder data against D:\task_173278106575060\mozharness\external_tools\performance-artifact-schema.json
[task 2024-11-28T08:42:23.745Z] 08:42:23     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "xpcshell.xpcshell.2.overall", "extraOptions": ["e10s", "taskcluster-Standard_F8s_v2"], "subtests": [{"name": "cpu_percent", "value": 33.78220161673801}, {"name": "io_write_bytes", "value": 321550336}, {"name": "io.read_bytes", "value": 320588800}, {"name": "io_write_time", "value": 0}, {"name": "io_read_time", "value": 1}]}, {"name": "xpcshell.xpcshell.2.start-pulseaudio", "subtests": [{"name": "time", "value": 0.0}, {"name": "cpu_percent", "value": 0}]}, {"name": "xpcshell.xpcshell.2.install", "subtests": [{"name": "time", "value": 3.046999999999997}, {"name": "cpu_percent", "value": 46.91}]}, {"name": "xpcshell.xpcshell.2.stage-files", "subtests": [{"name": "time", "value": 0.047000000000025466}, {"name": "cpu_percent", "value": 0}]}, {"name": "xpcshell.xpcshell.2.run-tests", "subtests": [{"name": "time", "value": 1048.859}, {"name": "cpu_percent", "value": 33.74908237200879}]}, {"name": "xpcshell.xpcshell.2.uninstall", "subtests": [{"name": "time", "value": 0.0}, {"name": "cpu_percent", "value": 0}]}]}
[task 2024-11-28T08:42:23.745Z] 08:42:23     INFO - Total resource usage - Wall time: 1053s; CPU: Can't collect data; Read bytes: 320588800; Write bytes: 321550336; Read time: 1; Write time: 0
[task 2024-11-28T08:42:23.745Z] 08:42:23     INFO - TinderboxPrint: I/O read bytes / time<br/>320,588,800 / 1
[task 2024-11-28T08:42:23.745Z] 08:42:23     INFO - TinderboxPrint: I/O write bytes / time<br/>321,550,336 / 0
[task 2024-11-28T08:42:23.745Z] 08:42:23     INFO - TinderboxPrint: CPU idle<br/>5,591.2 (66.4%)
[task 2024-11-28T08:42:23.745Z] 08:42:23     INFO - TinderboxPrint: CPU system<br/>1,150.7 (13.7%)
[task 2024-11-28T08:42:23.745Z] 08:42:23     INFO - TinderboxPrint: CPU user<br/>1,669.5 (19.8%)
[task 2024-11-28T08:42:23.749Z] 08:42:23     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-11-28T08:42:23.751Z] 08:42:23     INFO - install - Wall time: 3s; CPU: 47%; Read bytes: 57344; Write bytes: 107970560; Read time: 0; Write time: 0
[task 2024-11-28T08:42:23.754Z] 08:42:23     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-11-28T08:42:23.821Z] 08:42:23     INFO - run-tests - Wall time: 1049s; CPU: 34%; Read bytes: 320531456; Write bytes: 213579776; Read time: 1; Write time: 0
[task 2024-11-28T08:42:23.825Z] 08:42:23     INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-11-28T08:42:27.322Z] 08:42:27  WARNING - returning nonzero exit status 2
[taskcluster 2024-11-28T08:42:27.481Z]    Exit Code: 2
[taskcluster 2024-11-28T08:42:27.481Z]    User Time: 15.625ms
[taskcluster 2024-11-28T08:42:27.481Z]  Kernel Time: 31.25ms
[taskcluster 2024-11-28T08:42:27.481Z]    Wall Time: 19m46.1357749s
[taskcluster 2024-11-28T08:42:27.481Z]       Result: FAILED
[taskcluster 2024-11-28T08:42:27.481Z] === Task Finished ===
[taskcluster 2024-11-28T08:42:27.481Z] Task Duration: 19m46.1417812s
[taskcluster 2024-11-28T08:42:28.212Z] Uploading artifact public/test_info/system-info.log from file D:\task_173278106575060\build\blobber_upload_dir\system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2025-11-28T06:05:06.219Z
[taskcluster 2024-11-28T08:42:28.212Z] Uploading artifact public/logs/localconfig.json from file D:\task_173278106575060\logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2025-11-28T06:05:06.219Z
[taskcluster 2024-11-28T08:42:28.215Z] Uploading artifact public/test_info/profile_resource-usage.json from file D:\task_173278106575060\build\blobber_upload_dir\profile_resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-11-28T06:05:06.219Z
[taskcluster 2024-11-28T08:42:28.217Z] Uploading artifact public/test_info/xpcshell_errorsummary.log from file D:\task_173278106575060\build\blobber_upload_dir\xpcshell_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2025-11-28T06:05:06.219Z
[taskcluster 2024-11-28T08:42:28.219Z] Uploading artifact public/test_info/resource-usage.json from file D:\task_173278106575060\build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-11-28T06:05:06.219Z
[taskcluster 2024-11-28T08:42:28.865Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2025-11-28T06:05:06.219Z
[taskcluster:error] exit status 2

Hi! This bug seems to have started since your push according to the backfill range. Could you please take a look? Thanks!

Flags: needinfo?(aosmond)
Keywords: regression
Regressed by: 1933840
You need to log in before you can comment on or make changes to this bug.