Closed Bug 1703551 Opened 4 years ago Closed 4 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | browser/modules/test/browser/browser_UsageTelemetry.js | application timed out after 370 seconds with no output

Categories

(Toolkit :: Telemetry, defect, P5)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

INFO - TEST-PASS | browser/modules/test/browser/browser_UsageTelemetry.js | LOADED_TAB_COUNT - Navigated in existing tab - {"1":0,"2":2,"3":2,"4":0} deepEqual {"1":0,"2":2,"3":2,"4":0} - 
[task 2021-04-07T13:09:59.637Z] 13:09:58     INFO - Buffered messages finished
[task 2021-04-07T13:10:01.957Z] 13:10:01    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/modules/test/browser/browser_UsageTelemetry.js | application timed out after 370 seconds with no output
[task 2021-04-07T13:10:05.053Z] 13:10:04    ERROR - Force-terminating active process(es).
[task 2021-04-07T13:10:09.495Z] 13:10:08     INFO - Determining child pids from psutil...
[task 2021-04-07T13:10:15.958Z] 13:10:15     INFO - [1635, 1659, 1715, 1785, 1750, 1814, 1947, 1957]
[task 2021-04-07T13:10:20.016Z] 13:10:19     INFO - ==> process 1568 launched child process 1583
[task 2021-04-07T13:10:23.500Z] 13:10:22     INFO - ==> process 1568 launched child process 1635
[task 2021-04-07T13:10:26.079Z] 13:10:25     INFO - ==> process 1568 launched child process 1659
[task 2021-04-07T13:10:29.557Z] 13:10:28     INFO - ==> process 1568 launched child process 1715
[task 2021-04-07T13:10:35.651Z] 13:10:34     INFO - ==> process 1568 launched child process 1750
[task 2021-04-07T13:10:44.336Z] 13:10:43     INFO - ==> process 1568 launched child process 1785
[task 2021-04-07T13:10:49.539Z] 13:10:48     INFO - ==> process 1568 launched child process 1814
[task 2021-04-07T13:10:53.233Z] 13:10:52     INFO - ==> process 1568 launched child process 1957
[task 2021-04-07T13:10:56.853Z] 13:10:55     INFO - Found child pids: set([1635, 1750, 1947, 1583, 1715, 1814, 1785, 1659, 1957])
[task 2021-04-07T13:11:08.269Z] 13:11:07     INFO - Failed to get child procs
[task 2021-04-07T13:11:10.763Z] 13:11:08     INFO - Killing process: 1635
[task 2021-04-07T13:11:16.252Z] 13:11:15     INFO - TEST-INFO | started process screentopng
[task 2021-04-07T13:27:55.719Z] 13:27:55     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', u'browser/modules/test/browser/browser.ini', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', u'--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LkFCKHaqRFKAj_6LWGn_aw/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime']
[task 2021-04-07T13:27:55.740Z] 13:27:55    ERROR - timed out after 1000 seconds of no output
[task 2021-04-07T13:27:55.740Z] 13:27:55    ERROR - Return code: -15
[task 2021-04-07T13:27:55.740Z] 13:27:55    ERROR - No suite end message was emitted by this harness.
[task 2021-04-07T13:27:55.740Z] 13:27:55     INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>109/0/0
[task 2021-04-07T13:27:55.740Z] 13:27:55    ERROR - # TBPL FAILURE #
[task 2021-04-07T13:27:55.740Z] 13:27:55  WARNING - setting return code to 2
[task 2021-04-07T13:27:55.740Z] 13:27:55    ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2021-04-07T13:27:55.740Z] 13:27:55     INFO - Running post-action listener: _package_coverage_data
[task 2021-04-07T13:27:55.740Z] 13:27:55     INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-07T13:27:55.740Z] 13:27:55     INFO - Running post-action listener: process_java_coverage_data
[task 2021-04-07T13:27:55.740Z] 13:27:55     INFO - [mozharness: 2021-04-07 13:27:55.617080Z] Finished run-tests step (success)
[task 2021-04-07T13:27:55.740Z] 13:27:55     INFO - Running post-run listener: _resource_record_post_run
[task 2021-04-07T13:27:57.034Z] 13:27:56     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 22.931364922206523}, {"name": "io_write_bytes", "value": 2227527680}, {"name": "io.read_bytes", "value": 595328094208}, {"name": "io_write_time", "value": 281900}, {"name": "io_read_time", "value": 75711000}], "extraOptions": ["e10s", "taskcluster-c5.xlarge"], "name": "mochitest.mochitest-browser-chrome.overall"}, {"subtests": [{"name": "time", "value": 0.01771092414855957}], "name": "mochitest.mochitest-browser-chrome.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 31.707615852355957}, {"name": "cpu_percent", "value": 25.166666666666668}], "name": "mochitest.mochitest-browser-chrome.install"}, {"subtests": [{"name": "time", "value": 0.0002110004425048828}], "name": "mochitest.mochitest-browser-chrome.stage-files"}, {"subtests": [{"name": "time", "value": 2138.312267065048}, {"name": "cpu_percent", "value": 22.82814814814815}], "name": "mochitest.mochitest-browser-chrome.run-tests"}]}
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - Total resource usage - Wall time: 2170s; CPU: 23.0%; Read bytes: 595328094208; Write bytes: 2227527680; Read time: 75711000; Write time: 281900
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: CPU usage<br/>22.8%
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: I/O read bytes / time<br/>595,328,094,208 / 75,711,000
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: I/O write bytes / time<br/>2,227,527,680 / 281,900
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: CPU idle<br/>959.3 (11.1%)
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: CPU iowait<br/>6,793.2 (78.7%)
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: CPU system<br/>319.7 (3.7%)
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: CPU user<br/>558.4 (6.5%)
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - install - Wall time: 32s; CPU: 25.0%; Read bytes: 0; Write bytes: 1437503488; Read time: 0; Write time: 146280
[task 2021-04-07T13:27:57.043Z] 13:27:56     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-04-07T13:27:57.043Z] 13:27:57     INFO - run-tests - Wall time: 2138s; CPU: 23.0%; Read bytes: 595328049152; Write bytes: 521584640; Read time: 75710768; Write time: 95308
[task 2021-04-07T13:27:57.137Z] 13:27:57  WARNING - returning nonzero exit status 2
[task 2021-04-07T13:27:57.272Z] cleanup
[task 2021-04-07T13:27:57.272Z] + cleanup
[task 2021-04-07T13:27:57.272Z] + local rv=2
[task 2021-04-07T13:27:57.272Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-04-07T13:27:57.272Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-04-07T13:27:57.438Z] + '[' ']'
[task 2021-04-07T13:27:57.438Z] + true
[task 2021-04-07T13:27:57.438Z] + cleanup_xvfb
[task 2021-04-07T13:27:57.439Z] ++ pidof Xvfb
[task 2021-04-07T13:27:57.449Z] + local xvfb_pid=50
[task 2021-04-07T13:27:57.449Z] + local vnc=false
[task 2021-04-07T13:27:57.449Z] + local interactive=false
[task 2021-04-07T13:27:57.449Z] + '[' -n 50 ']'
[task 2021-04-07T13:27:57.449Z] + [[ false == false ]]
[task 2021-04-07T13:27:57.449Z] + [[ false == false ]]
[task 2021-04-07T13:27:57.449Z] + kill 50
[task 2021-04-07T13:27:57.449Z] + screen -XS xvfb quit
[task 2021-04-07T13:27:57.735Z] + exit 2
[taskcluster 2021-04-07 13:27:58.788Z] === Task Finished ===
[taskcluster 2021-04-07 13:28:00.728Z] Unsuccessful task run with exit code: 2 completed in 2251.26 seconds```

The only code between the last printed check "LOADED TAB COUNT - Navigated in existing tab" and the next printed check are a bunch of synchronous code (arithmetic and snapshots) plus a call to await BrowserTestUtils.openNewBrowserWindow

The only recent-ish change in that land was the addition of some profiler markers. Florian, that wouldn't cause tests to hang would it?

Flags: needinfo?(florian)

With a single failure, it's hard to say what happened. Profiler markers shouldn't cause hangs (and even less so if the profiler wasn't running).

Flags: needinfo?(florian)

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

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