Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=403977137&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/AI02rqntTamCr-3eBh0TVg/runs/0/artifacts/public/logs/live_backing.log
[task 2023-01-30T17:55:33.201Z] 17:55:33 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabKeyBehavior.js | The urlbar view should be closed. - true == true -
[task 2023-01-30T17:55:33.201Z] 17:55:33 INFO - Leaving test bound tabOnTopSites
[task 2023-01-30T17:55:33.201Z] 17:55:33 INFO - Buffered messages logged at 17:49:23
[task 2023-01-30T17:55:33.201Z] 17:55:33 INFO - Console message: [JavaScript Error: "Timeout while waiting for extension child to shutdown: "Generated extension" (ID: example@tests.mozilla.org, moz-extension://88c26e3f-c34e-462c-96cf-3d617774a88b/)" {file: "resource://gre/modules/Extension.jsm" line: 3408}]
[task 2023-01-30T17:55:33.201Z] 17:55:33 INFO - shutdown@resource://gre/modules/Extension.jsm:3408:10
[task 2023-01-30T17:55:33.202Z] 17:55:33 INFO -
[task 2023-01-30T17:55:33.202Z] 17:55:33 INFO - Buffered messages finished
[task 2023-01-30T17:55:33.203Z] 17:55:33 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/urlbar/tests/browser/browser_tabKeyBehavior.js | application timed out after 370 seconds with no output
[task 2023-01-30T17:55:33.204Z] 17:55:33 ERROR - Force-terminating active process(es).
[task 2023-01-30T17:55:33.204Z] 17:55:33 INFO - Determining child pids from psutil...
[task 2023-01-30T17:55:33.204Z] 17:55:33 INFO - [1697, 1721, 1773, 1814, 1831, 1926, 2371, 13050, 13062, 13087]
[task 2023-01-30T17:55:33.204Z] 17:55:33 INFO - ==> process 1597 launched child process 1615
[task 2023-01-30T17:55:33.205Z] 17:55:33 INFO - ==> process 1597 launched child process 1697
[task 2023-01-30T17:55:33.205Z] 17:55:33 INFO - ==> process 1597 launched child process 1721
[task 2023-01-30T17:55:33.205Z] 17:55:33 INFO - ==> process 1597 launched child process 1773
[task 2023-01-30T17:55:33.205Z] 17:55:33 INFO - ==> process 1597 launched child process 1777
[task 2023-01-30T17:55:33.206Z] 17:55:33 INFO - ==> process 1597 launched child process 1814
[task 2023-01-30T17:55:33.206Z] 17:55:33 INFO - ==> process 1597 launched child process 1831
[task 2023-01-30T17:55:33.206Z] 17:55:33 INFO - ==> process 1597 launched child process 1897
[task 2023-01-30T17:55:33.207Z] 17:55:33 INFO - ==> process 1597 launched child process 1933
[task 2023-01-30T17:55:33.207Z] 17:55:33 INFO - ==> process 1597 launched child process 1949
[task 2023-01-30T17:55:33.208Z] 17:55:33 INFO - ==> process 1597 launched child process 2026
[task 2023-01-30T17:55:33.208Z] 17:55:33 INFO - ==> process 1597 launched child process 2051
[task 2023-01-30T17:55:33.209Z] 17:55:33 INFO - ==> process 1597 launched child process 2076
[task 2023-01-30T17:55:33.209Z] 17:55:33 INFO - ==> process 1597 launched child process 2101
[task 2023-01-30T17:55:33.210Z] 17:55:33 INFO - ==> process 1597 launched child process 2126
[task 2023-01-30T17:55:33.210Z] 17:55:33 INFO - ==> process 1597 launched child process 2136
[task 2023-01-30T17:55:33.210Z] 17:55:33 INFO - ==> process 1597 launched child process 2176
[task 2023-01-30T17:55:33.211Z] 17:55:33 INFO - ==> process 1597 launched child process 2203
[task 2023-01-30T17:55:33.211Z] 17:55:33 INFO - ==> process 1597 launched child process 2228
[task 2023-01-30T17:55:33.212Z] 17:55:33 INFO - ==> process 1597 launched child process 2253
[task 2023-01-30T17:55:33.212Z] 17:55:33 INFO - ==> process 1597 launched child process 2278
[task 2023-01-30T17:55:33.212Z] 17:55:33 INFO - ==> process 1597 launched child process 2321
[task 2023-01-30T17:55:33.213Z] 17:55:33 INFO - ==> process 1597 launched child process 2342
[task 2023-01-30T17:55:33.213Z] 17:55:33 INFO - ==> process 1597 launched child process 2371
[task 2023-01-30T17:55:33.214Z] 17:55:33 INFO - ==> process 1597 launched child process 2392
[task 2023-01-30T17:55:33.214Z] 17:55:33 INFO - ==> process 1597 launched child process 2417
[task 2023-01-30T17:55:33.214Z] 17:55:33 INFO - ==> process 1597 launched child process 2442
[task 2023-01-30T17:55:33.215Z] 17:55:33 INFO - ==> process 1597 launched child process 2452
[task 2023-01-30T17:55:33.215Z] 17:55:33 INFO - ==> process 1597 launched child process 2488
[task 2023-01-30T17:55:33.216Z] 17:55:33 INFO - ==> process 1597 launched child process 2521
[task 2023-01-30T17:55:33.216Z] 17:55:33 INFO - ==> process 1597 launched child process 2546
[task 2023-01-30T17:55:33.216Z] 17:55:33 INFO - ==> process 1597 launched child process 2571
[task 2023-01-30T17:55:33.217Z] 17:55:33 INFO - ==> process 1597 launched child process 2592
[task 2023-01-30T17:55:33.217Z] 17:55:33 INFO - ==> process 1597 launched child process 2613
[task 2023-01-30T17:55:33.217Z] 17:55:33 INFO - ==> process 1597 launched child process 2634
[task 2023-01-30T17:55:33.218Z] 17:55:33 INFO - ==> process 1597 launched child process 2667
[task 2023-01-30T17:55:33.218Z] 17:55:33 INFO - ==> process 1597 launched child process 2692
[task 2023-01-30T17:55:33.219Z] 17:55:33 INFO - ==> process 1597 launched child process 2735
[task 2023-01-30T17:55:33.219Z] 17:55:33 INFO - ==> process 1597 launched child process 2760
[task 2023-01-30T17:55:33.220Z] 17:55:33 INFO - ==> process 1597 launched child process 2773
[task 2023-01-30T17:55:33.220Z] 17:55:33 INFO - ==> process 1597 launched child process 2809
[task 2023-01-30T17:55:33.221Z] 17:55:33 INFO - ==> process 1597 launched child process 2837
[task 2023-01-30T17:55:33.221Z] 17:55:33 INFO - ==> process 1597 launched child process 2863
[task 2023-01-30T17:55:33.221Z] 17:55:33 INFO - ==> process 1597 launched child process 2884
[task 2023-01-30T17:55:33.222Z] 17:55:33 INFO - ==> process 1597 launched child process 2921
[task 2023-01-30T17:55:33.222Z] 17:55:33 INFO - ==> process 1597 launched child process 2963
[task 2023-01-30T17:55:33.223Z] 17:55:33 INFO - ==> process 1597 launched child process 2988
[task 2023-01-30T17:55:33.223Z] 17:55:33 INFO - ==> process 1597 launched child process 3017
[task 2023-01-30T17:55:33.223Z] 17:55:33 INFO - ==> process 1597 launched child process 3038
[task 2023-01-30T17:55:33.224Z] 17:55:33 INFO - ==> process 1597 launched child process 3067
[task 2023-01-30T17:55:33.224Z] 17:55:33 INFO - ==> process 1597 launched child process 3099
[task 2023-01-30T17:55:33.225Z] 17:55:33 INFO - ==> process 1597 launched child process 3124
[task 2023-01-30T17:55:33.225Z] 17:55:33 INFO - ==> process 1597 launched child process 3137
[task 2023-01-30T17:55:33.225Z] 17:55:33 INFO - ==> process 1597 launched child process 3174
[task 2023-01-30T17:55:33.226Z] 17:55:33 INFO - ==> process 1597 launched child process 3205
[task 2023-01-30T17:55:33.226Z] 17:55:33 INFO - ==> process 1597 launched child process 3259
[task 2023-01-30T17:55:33.227Z] 17:55:33 INFO - ==> process 1597 launched child process 3291
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3322
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3343
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3364
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3403
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3424
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3441
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3444
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3478
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3526
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3543
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3583
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3610
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3655
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3660
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3723
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3752
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3777
[task 2023-01-30T17:55:33.231Z] 17:55:33 INFO - ==> process 1597 launched child process 3798
[task 2023-01-30T17:55:33.234Z] 17:55:33 INFO - ==> process 1597 launched child process 3823
[task 2023-01-30T17:55:33.234Z] 17:55:33 INFO - ==> process 1597 launched child process 3848
[task 2023-01-30T17:55:33.234Z] 17:55:33 INFO - ==> process 1597 launched child process 3873
[task 2023-01-30T17:56:34.557Z] 17:56:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-01-30T17:56:34.558Z] 17:56:34 INFO - Can't trigger Breakpad, just killing process
[task 2023-01-30T17:56:34.559Z] 17:56:34 INFO - Error: Failed to kill process 12280: process PID not found (pid=12280)
[task 2023-01-30T17:56:34.559Z] 17:56:34 INFO - Killing process: 4090
[task 2023-01-30T17:56:34.559Z] 17:56:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-01-30T17:56:34.560Z] 17:56:34 INFO - Can't trigger Breakpad, just killing process
[task 2023-01-30T17:56:34.560Z] 17:56:34 INFO - Error: Failed to kill process 4090: process PID not found (pid=4090)
[task 2023-01-30T17:56:34.561Z] 17:56:34 INFO - Killing process: 1597
[task 2023-01-30T17:56:34.561Z] 17:56:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-01-30T17:56:34.561Z] 17:56:34 INFO - Can't trigger Breakpad, just killing process
[task 2023-01-30T17:57:04.580Z] 17:57:04 INFO - psutil found pid 1597 dead
[task 2023-01-30T17:57:04.580Z] 17:57:04 INFO - failed to kill pid 13050 after 30s
[task 2023-01-30T17:57:04.581Z] 17:57:04 INFO - failed to kill pid 1926 after 30s
[task 2023-01-30T17:57:04.581Z] 17:57:04 INFO - psutil found pid 1597 dead
[task 2023-01-30T18:13:44.585Z] 18:13:44 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', 'browser/components/urlbar/tests/browser/browser.ini', '--setpref=gfx.webrender.software=true', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--setpref=javascript.options.mem.gc_parallel_marking=true', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aAkncMDSREygy0h1hdTAag/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 2023-01-30T18:13:44.585Z] 18:13:44 ERROR - timed out after 1000 seconds of no output
[task 2023-01-30T18:13:44.585Z] 18:13:44 ERROR - Return code: -15
[task 2023-01-30T18:13:44.586Z] 18:13:44 ERROR - No suite end message was emitted by this harness.
[task 2023-01-30T18:13:44.586Z] 18:13:44 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>329/0/0
[task 2023-01-30T18:13:44.586Z] 18:13:44 ERROR - # TBPL FAILURE #
[task 2023-01-30T18:13:44.586Z] 18:13:44 WARNING - setting return code to 2
[task 2023-01-30T18:13:44.587Z] 18:13:44 ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2023-01-30T18:13:44.587Z] 18:13:44 INFO - Running post-action listener: _package_coverage_data
[task 2023-01-30T18:13:44.587Z] 18:13:44 INFO - Running post-action listener: _resource_record_post_action
[task 2023-01-30T18:13:44.587Z] 18:13:44 INFO - Running post-action listener: process_java_coverage_data
[task 2023-01-30T18:13:44.587Z] 18:13:44 INFO - [mozharness: 2023-01-30 18:13:44.587552Z] Finished run-tests step (success)
[task 2023-01-30T18:13:44.588Z] 18:13:44 INFO - [mozharness: 2023-01-30 18:13:44.587617Z] Running uninstall step.
[task 2023-01-30T18:13:44.588Z] 18:13:44 INFO - Running pre-action listener: _resource_record_pre_action
[task 2023-01-30T18:13:44.588Z] 18:13:44 INFO - Running main action method: uninstall
[task 2023-01-30T18:13:44.588Z] 18:13:44 INFO - Skipping uninstall for non-MSIX test
[task 2023-01-30T18:13:44.588Z] 18:13:44 INFO - Running post-action listener: _resource_record_post_action
[task 2023-01-30T18:13:44.588Z] 18:13:44 INFO - [mozharness: 2023-01-30 18:13:44.587892Z] Finished uninstall step (success)
[task 2023-01-30T18:13:44.588Z] 18:13:44 INFO - Running post-run listener: _resource_record_post_run
[task 2023-01-30T18:13:44.760Z] 18:13:44 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2023-01-30T18:13:44.763Z] 18:13:44 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-browser-chrome.overall", "extraOptions": ["e10s", "taskcluster-projects/887720501152/machineTypes/n2-standard-4"], "subtests": [{"name": "cpu_percent", "value": 31.923387320044213}, {"name": "io_write_bytes", "value": 4596129792}, {"name": "io.read_bytes", "value": 729088}, {"name": "io_write_time", "value": 931144}, {"name": "io_read_time", "value": 40}]}, {"name": "mochitest.mochitest-browser-chrome.start-pulseaudio", "subtests": [{"name": "time", "value": 0.022855281829833984}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-browser-chrome.install", "subtests": [{"name": "time", "value": 46.36830258369446}, {"name": "cpu_percent", "value": 25.278333333333336}]}, {"name": "mochitest.mochitest-browser-chrome.stage-files", "subtests": [{"name": "time", "value": 0.0006592273712158203}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-browser-chrome.run-tests", "subtests": [{"name": "time", "value": 3570.6222999095917}, {"name": "cpu_percent", "value": 32.00913043478253}]}, {"name": "mochitest.mochitest-browser-chrome.uninstall", "subtests": [{"name": "time", "value": 0.0001850128173828125}, {"name": "cpu_percent", "value": 0}]}]}
[task 2023-01-30T18:13:44.763Z] 18:13:44 INFO - Total resource usage - Wall time: 3617s; CPU: Can't collect data; Read bytes: 729088; Write bytes: 4596129792; Read time: 40; Write time: 931144
[task 2023-01-30T18:13:44.764Z] 18:13:44 INFO - TinderboxPrint: I/O read bytes / time<br/>729,088 / 40
[task 2023-01-30T18:13:44.764Z] 18:13:44 INFO - TinderboxPrint: I/O write bytes / time<br/>4,596,129,792 / 931,144
[task 2023-01-30T18:13:44.764Z] 18:13:44 INFO - TinderboxPrint: CPU idle<br/>9,809.5 (68.1%)
[task 2023-01-30T18:13:44.764Z] 18:13:44 INFO - TinderboxPrint: CPU system<br/>473.6 (3.3%)
[task 2023-01-30T18:13:44.764Z] 18:13:44 INFO - TinderboxPrint: CPU user<br/>4,111.1 (28.5%)
[task 2023-01-30T18:13:44.764Z] 18:13:44 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2023-01-30T18:13:44.765Z] 18:13:44 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-01-30T18:13:44.766Z] 18:13:44 INFO - install - Wall time: 46s; CPU: 25%; Read bytes: 0; Write bytes: 754896896; Read time: 0; Write time: 116196
[task 2023-01-30T18:13:44.767Z] 18:13:44 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-01-30T18:13:44.790Z] 18:13:44 INFO - run-tests - Wall time: 3571s; CPU: 32%; Read bytes: 16384; Write bytes: 3841232896; Read time: 32; Write time: 814948
[task 2023-01-30T18:13:44.792Z] 18:13:44 INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-01-30T18:13:45.337Z] 18:13:45 WARNING - returning nonzero exit status 2
[task 2023-01-30T18:13:45.397Z] cleanup
[task 2023-01-30T18:13:45.397Z] + cleanup
[task 2023-01-30T18:13:45.397Z] + local rv=2
[task 2023-01-30T18:13:45.397Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2023-01-30T18:13:45.397Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2023-01-30T18:13:45.399Z] + '[' ']'
[task 2023-01-30T18:13:45.399Z] + true
[task 2023-01-30T18:13:45.399Z] + cleanup_xvfb
[task 2023-01-30T18:13:45.399Z] ++ pidof Xvfb
[task 2023-01-30T18:13:45.409Z] + local xvfb_pid=50
[task 2023-01-30T18:13:45.410Z] + local vnc=false
[task 2023-01-30T18:13:45.410Z] + local interactive=false
[task 2023-01-30T18:13:45.410Z] + '[' -n 50 ']'
[task 2023-01-30T18:13:45.410Z] + [[ false == false ]]
[task 2023-01-30T18:13:45.410Z] + [[ false == false ]]
[task 2023-01-30T18:13:45.410Z] + kill 50
[task 2023-01-30T18:13:45.410Z] + screen -XS xvfb quit
[task 2023-01-30T18:13:45.415Z] + exit 2
[taskcluster 2023-01-30 18:13:45.881Z] === Task Finished ===
[taskcluster 2023-01-30 18:13:50.803Z] Unsuccessful task run with exit code: 2 completed in 3736.446 seconds
Description
•