Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=413448769&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VZPPYOyzSiq7lf2OK1_dNA/runs/3/artifacts/public/logs/live_backing.log
[task 2023-04-23T05:43:11.702Z] 05:43:11 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_whereToOpen.js | New URL would reuse the current empty tab -
[task 2023-04-23T05:43:11.702Z] 05:43:11 INFO - Leaving test bound reuseEmptyTab
[task 2023-04-23T05:43:11.702Z] 05:43:11 INFO - Entering test bound openInCurrentTab
[task 2023-04-23T05:43:11.702Z] 05:43:11 INFO - Enter, non-empty tab, default prefs
[task 2023-04-23T05:43:11.702Z] 05:43:11 INFO - Buffered messages finished
[task 2023-04-23T05:43:11.702Z] 05:43:11 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/urlbar/tests/browser/browser_whereToOpen.js | application timed out after 370 seconds with no output
[task 2023-04-23T05:43:11.702Z] 05:43:11 WARNING - Force-terminating active process(es).
[task 2023-04-23T05:43:11.702Z] 05:43:11 INFO - Determining child pids from psutil...
[task 2023-04-23T05:43:11.724Z] 05:43:11 INFO - [2212, 2231, 2293, 2295, 2308, 2325, 3004, 13657, 13669, 13687, 13694, 13696]
[task 2023-04-23T05:43:11.731Z] 05:43:11 INFO - ==> process 2147 launched child process 2163
[task 2023-04-23T05:43:11.733Z] 05:43:11 INFO - ==> process 2147 launched child process 2212
[task 2023-04-23T05:43:11.737Z] 05:43:11 INFO - ==> process 2147 launched child process 2231
[task 2023-04-23T05:43:11.737Z] 05:43:11 INFO - ==> process 2147 launched child process 2293
[task 2023-04-23T05:43:11.738Z] 05:43:11 INFO - ==> process 2147 launched child process 2295
[task 2023-04-23T05:43:11.740Z] 05:43:11 INFO - ==> process 2147 launched child process 2296
[task 2023-04-23T05:43:32.092Z] 05:43:12 INFO - ==> process 2147 launched child process 13687
[task 2023-04-23T05:43:32.092Z] 05:43:12 INFO - ==> process 2147 launched child process 13694
[task 2023-04-23T05:43:32.092Z] 05:43:12 INFO - ==> process 2147 launched child process 13696
[task 2023-04-23T05:43:32.092Z] 05:43:12 INFO - Found child pids: {8192, 8193, 8202, 10252, 8215, 4122, 12320, 10276, 6183, 10289, 4150, 12344, 6201, 6207, 12360, 12362, 4175, 10319, 8274, 6242, 10344, 8299, 12401, 2163, 4220, 10369, 6274, 8331, 12427, 6297, 10394, 4254, 2212, 8356, 12457, 8363, 10420, 2231, 4280, 12482, 6342, 10446, 12494, 4308, 12500, 8406, 12502, 10476, 8432, 4338, 2293, 2295, 2296, 4354, 2308, 10501, 8458, 2325, 10517, 12573, 6430, 4388, 10533, 12580, 12586, 12593, 4405, 12603, 8508, 10558, 6465, 4430, 8533, 10583, 6496, 6498, 2404, 4459, 10608, 8567, 12671, 12676, 4485, 2440, 8588, 6544, 10641, 10649, 4507, 2461, 4511, 10660, 6565, 8614, 12724, 6591, 12739, 8648, 10698, 12756, 4575, 2529, 8676, 6629, 8678, 10724, 12782, 2555, 4605, 8704, 10759, 12807, 6666, 2580, 10782, 4642, 8739, 12837, 8742, 6696, 2605, 4655, 2612, 12864, 10819, 8776, 6733, 12880, 12882, 10842, 4703, 8799, 2662, 2664, 10858, 10867, 12921, 4732, 8832, 6793, 2706, 4757, 12949, 10906, 8860, 6816, 2731, 4779, 2734, 12974, 10931, 12982, 12992, 6851, 10947, 4805, 10951, 6866, 4820, 10966, 4826, 2784, 8934, 13031, 4849, 6899, 2809, 6907, 13054, 11013, 8966, 2835, 2841, 8987, 8988, 4893, 4894, 6941, 11038, 13084, 6949, 9000, 13107, 13108, 13110, 11063, 4934, 11088, 6993, 11091, 2900, 9057, 4966, 7016, 2925, 13174, 9086, 11139, 7045, 5001, 2954, 5002, 13199, 13201, 9117, 2978, 11171, 7079, 11188, 13238, 9144, 3004, 3007, 5056, 7106, 13250, 11205, 11209, 9167, 5074, 5076, 7131, 13278, 13287, 9192, 3058, 11255, 13313, 5123, 3076, 13316, 9222, 11280, 7189, 3096, 9248, 11305, 5166, 7214, 13358, 9268, 3125, 13379, 11333, 5194, 7244, 3150, 3153, 7260, 13404, 5214, 11358, 9323, 9325, 11374, 11375, 7280, 11378, 13433, 5244, 9340, 5246, 3202, 7311, 13458, 13459, 3223, 9371, 3245, 5294, 11440, 13501, 7358, 9406, 3266, 5320, 11466, 9428, 13528, 5345, 3299, 11496, 7403, 9461, 13557, 3329, 5378, 11521, 11523, 7429, 7430, 9482, 13589, 13591, 3354, 11548, 5407, 11553, 5410, 9523, 3380, 7478, 13630, 3401, 9545, 13643, 11603, 5462, 13657, 7517, 13669, 3432, 5481, 11632, 9587, 13687, 13694, 7550, 13696, 9598, 3458, 5507, 9605, 11657, 11659, 9621, 11671, 3482, 7579, 5534, 3508, 5559, 7608, 9670, 11720, 3534, 5584, 7645, 3555, 9701, 11754, 5614, 7667, 5623, 3580, 11782, 9735, 7696, 11798, 11800, 3609, 5666, 5667, 7726, 3635, 9784, 11838, 7747, 5714, 9811, 9812, 3669, 9814, 11867, 3676, 7781, 5741, 11888, 7803, 11909, 3718, 5766, 11910, 11912, 9868, 7837, 5795, 3748, 9893, 7863, 7865, 5822, 9920, 11972, 3785, 5848, 9945, 3805, 7912, 12009, 12012, 5874, 9970, 7925, 3837, 12040, 5900, 9997, 12046, 9999, 12053, 3863, 7963, 5929, 7980, 3893, 10047, 12101, 10055, 5966, 8014, 5968, 5969, 12121, 3933, 8030, 8050, 12148, 12151, 3961, 12162, 6024, 10124, 3983, 8093, 8094, 6049, 8097, 10150, 10153, 4012, 12209, 12212, 6076, 10177, 10187, 4047, 12239, 6103, 8167, 4073, 12265, 12268, 4079, 6128, 10236}
[task 2023-04-23T05:43:32.191Z] 05:43:12 INFO - Failed to get child procs
[task 2023-04-23T05:43:32.191Z] 05:43:12 INFO - Killing process: 8192
[task 2023-04-23T05:43:32.191Z] 05:43:12 INFO - TEST-INFO | started process screentopng
[task 2023-04-23T05:43:32.191Z] 05:43:30 INFO - =================================================================
[task 2023-04-23T05:43:32.191Z] 05:43:30 ERROR - ==13750==ERROR: AddressSanitizer: out of memory: allocator is trying to allocate 0x57e400 bytes
[task 2023-04-23T05:43:32.191Z] 05:43:30 ERROR - ==13750==ERROR: AddressSanitizer: out of memory: failed to allocate 0x1a0000 (1703936) bytes of InternalMmapVector (error code: 12)
[task 2023-04-23T05:43:32.191Z] 05:43:30 INFO - ==13750==Process memory map follows:
[task 2023-04-23T05:43:32.191Z] 05:43:30 INFO - 0x00007fff7000-0x00008fff7000
[task 2023-04-23T05:43:32.191Z] 05:43:30 INFO - 0x00008fff7000-0x02008fff7000
<...>
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7f7f90720000-0x7f7f90747000 /lib/x86_64-linux-gnu/ld-2.27.so
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7f7f90794000-0x7f7f9092a000
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7f7f9092a000-0x7f7f90947000
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7f7f90947000-0x7f7f90948000 /lib/x86_64-linux-gnu/ld-2.27.so
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7f7f90948000-0x7f7f90949000 /lib/x86_64-linux-gnu/ld-2.27.so
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7f7f90949000-0x7f7f9094a000
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7ffdb50b2000-0x7ffdb50d3000 [stack]
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7ffdb5113000-0x7ffdb5116000 [vvar]
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0x7ffdb5116000-0x7ffdb5118000 [vdso]
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - 0xffffffffff600000-0xffffffffff601000 [vsyscall]
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - ==13750==End of process memory map.
[task 2023-04-23T05:43:32.213Z] 05:43:30 INFO - AddressSanitizer: CHECK failed: sanitizer_common.cpp:61 "((0 && "unable to mmap")) != (0)" (0x0, 0x0) (tid=13750)
[task 2023-04-23T06:00:10.312Z] 06:00:10 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/doh/test/browser/browser.ini', 'browser/components/urlbar/tests/browser/browser.ini', 'browser/components/urlbar/tests/ext/browser/browser.ini', 'browser/extensions/webcompat/tests/browser/browser.ini', 'dom/events/test/browser.ini', 'dom/serviceworkers/test/browser.ini', 'netwerk/cookie/test/browser/browser.ini', 'parser/htmlparser/tests/mochitest/browser.ini', 'toolkit/components/mozprotocol/tests/browser.ini', 'toolkit/components/printing/tests/browser.ini', 'toolkit/components/reader/test/browser.ini', '--setpref=gfx.webrender.software=true', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--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/TXGsVV3ZTZGg3-R6UJvlsg/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--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-04-23T06:00:10.312Z] 06:00:10 ERROR - timed out after 1000 seconds of no output
[task 2023-04-23T06:00:10.312Z] 06:00:10 INFO - Return code: -15
[task 2023-04-23T06:00:10.313Z] 06:00:10 ERROR - No suite end message was emitted by this harness.
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>235/0/0
[task 2023-04-23T06:00:10.314Z] 06:00:10 WARNING - setting return code to 2
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - Running post-action listener: _package_coverage_data
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - Running post-action listener: _resource_record_post_action
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - Running post-action listener: process_java_coverage_data
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - [mozharness: 2023-04-23 06:00:10.314689Z] Finished run-tests step (success)
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - [mozharness: 2023-04-23 06:00:10.314762Z] Running uninstall step.
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - Running pre-action listener: _resource_record_pre_action
[task 2023-04-23T06:00:10.314Z] 06:00:10 INFO - Running main action method: uninstall
[task 2023-04-23T06:00:10.315Z] 06:00:10 INFO - Skipping uninstall for non-MSIX test
[task 2023-04-23T06:00:10.315Z] 06:00:10 INFO - Running post-action listener: _resource_record_post_action
[task 2023-04-23T06:00:10.315Z] 06:00:10 INFO - [mozharness: 2023-04-23 06:00:10.315385Z] Finished uninstall step (success)
[task 2023-04-23T06:00:10.315Z] 06:00:10 INFO - Running post-run listener: _resource_record_post_run
[task 2023-04-23T06:00:10.492Z] 06:00:10 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2023-04-23T06:00:10.496Z] 06:00:10 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-browser-chrome.overall", "extraOptions": ["e10s", "taskcluster-projects/887720501152/machineTypes/n2-standard-2"], "subtests": [{"name": "cpu_percent", "value": 48.827952755905535}, {"name": "io_write_bytes", "value": 6524624896}, {"name": "io.read_bytes", "value": 650021842944}, {"name": "io_write_time", "value": 2599040}, {"name": "io_read_time", "value": 23667528}]}, {"name": "mochitest.mochitest-browser-chrome.start-pulseaudio", "subtests": [{"name": "time", "value": 0.02628159523010254}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-browser-chrome.install", "subtests": [{"name": "time", "value": 67.22793865203857}, {"name": "cpu_percent", "value": 50.56818181818182}]}, {"name": "mochitest.mochitest-browser-chrome.stage-files", "subtests": [{"name": "time", "value": 0.0009760856628417969}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-browser-chrome.run-tests", "subtests": [{"name": "time", "value": 2938.110898733139}, {"name": "cpu_percent", "value": 48.77897268180071}]}, {"name": "mochitest.mochitest-browser-chrome.uninstall", "subtests": [{"name": "time", "value": 0.0005099773406982422}, {"name": "cpu_percent", "value": 0}]}]}
[task 2023-04-23T06:00:10.497Z] 06:00:10 INFO - Total resource usage - Wall time: 3005s; CPU: Can't collect data; Read bytes: 650021842944; Write bytes: 6524624896; Read time: 23667528; Write time: 2599040
[task 2023-04-23T06:00:10.497Z] 06:00:10 INFO - TinderboxPrint: I/O read bytes / time<br/>650,021,842,944 / 23,667,528
[task 2023-04-23T06:00:10.497Z] 06:00:10 INFO - TinderboxPrint: I/O write bytes / time<br/>6,524,624,896 / 2,599,040
[task 2023-04-23T06:00:10.498Z] 06:00:10 INFO - TinderboxPrint: CPU idle<br/>2,702.2 (45.2%)
[task 2023-04-23T06:00:10.498Z] 06:00:10 INFO - TinderboxPrint: CPU iowait<br/>290.7 (4.9%)
[task 2023-04-23T06:00:10.498Z] 06:00:10 INFO - TinderboxPrint: CPU system<br/>855.1 (14.3%)
[task 2023-04-23T06:00:10.499Z] 06:00:10 INFO - TinderboxPrint: CPU user<br/>2,122.5 (35.5%)
[task 2023-04-23T06:00:10.499Z] 06:00:10 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2023-04-23T06:00:10.499Z] 06:00:10 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-04-23T06:00:10.500Z] 06:00:10 INFO - install - Wall time: 67s; CPU: 51%; Read bytes: 221184; Write bytes: 3742969856; Read time: 372; Write time: 2318480
[task 2023-04-23T06:00:10.501Z] 06:00:10 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-04-23T06:00:10.511Z] 06:00:10 INFO - run-tests - Wall time: 2938s; CPU: 49%; Read bytes: 650019491840; Write bytes: 2776027136; Read time: 23667132; Write time: 276736
[task 2023-04-23T06:00:10.513Z] 06:00:10 INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-04-23T06:00:10.757Z] 06:00:10 WARNING - returning nonzero exit status 2
[task 2023-04-23T06:00:10.797Z] cleanup
[task 2023-04-23T06:00:10.797Z] + cleanup
[task 2023-04-23T06:00:10.798Z] + local rv=2
[task 2023-04-23T06:00:10.798Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2023-04-23T06:00:10.798Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2023-04-23T06:00:10.808Z] + '[' ']'
[task 2023-04-23T06:00:10.808Z] + true
[task 2023-04-23T06:00:10.808Z] + cleanup_xvfb
[task 2023-04-23T06:00:10.809Z] ++ pidof Xvfb
[task 2023-04-23T06:00:10.830Z] + local xvfb_pid=48
[task 2023-04-23T06:00:10.831Z] + local vnc=false
[task 2023-04-23T06:00:10.832Z] + local interactive=false
[task 2023-04-23T06:00:10.833Z] + '[' -n 48 ']'
[task 2023-04-23T06:00:10.834Z] + [[ false == false ]]
[task 2023-04-23T06:00:10.834Z] + [[ false == false ]]
[task 2023-04-23T06:00:10.834Z] + kill 48
[task 2023-04-23T06:00:10.835Z] + screen -XS xvfb quit
[task 2023-04-23T06:00:10.894Z] + exit 2
[taskcluster 2023-04-23 06:00:14.043Z] === Task Finished ===
[taskcluster 2023-04-23 06:00:16.758Z] Unsuccessful task run with exit code: 2 completed in 3228.532 seconds
Description
•