Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=496772167&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WN-9z47QQa-NA_yJ6ISS_w/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/WN-9z47QQa-NA_yJ6ISS_w/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1
[task 2025-02-27T03:01:04.614Z] 03:01:04 INFO - TEST-START | browser/components/profiles/tests/browser/browser_test_last_tab.js
[task 2025-02-27T03:01:05.000Z] 03:01:05 INFO - TEST-INFO | started process screentopng
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - TEST-INFO | screentopng: exit 0
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Buffered messages logged at 03:01:04
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Entering setup bound
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Leaving setup bound
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Entering test bound test_browser_remains_open_after_closing_last_profiles_tab
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Buffered messages finished
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - TEST-UNEXPECTED-FAIL | browser/components/profiles/tests/browser/browser_test_last_tab.js | The current uri is 'about:newtab' and the browser didn't close - Got "about:editprofile", expected "about:newtab"
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Stack trace:
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:test_is:1654
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochitests/content/browser/browser/components/profiles/tests/browser/browser_test_last_tab.js:test_browser_remains_open_after_closing_last_profiles_tab:58
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:handleTask:1170
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1242
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1383
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1153
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Not taking screenshot here: see the one that was previously logged
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - TEST-UNEXPECTED-FAIL | browser/components/profiles/tests/browser/browser_test_last_tab.js | There is only 1 tab open - Got 2, expected 1
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - Stack trace:
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:test_is:1654
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochitests/content/browser/browser/components/profiles/tests/browser/browser_test_last_tab.js:test_browser_remains_open_after_closing_last_profiles_tab:63
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:handleTask:1170
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1242
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1383
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1153
[task 2025-02-27T03:01:05.205Z] 03:01:05 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2025-02-27T03:01:50.991Z] 03:01:50 INFO - Not taking screenshot here: see the one that was previously logged
[task 2025-02-27T03:01:50.992Z] 03:01:50 INFO - TEST-UNEXPECTED-FAIL | browser/components/profiles/tests/browser/browser_test_last_tab.js | Test timed out -
[task 2025-02-27T03:01:50.993Z] 03:01:50 INFO - GECKO(1082) | Completed ShutdownLeaks collections in process 1082
[task 2025-02-27T03:01:50.993Z] 03:01:50 INFO - TEST-START | Shutdown
[task 2025-02-27T03:01:50.993Z] 03:01:50 INFO - Browser Chrome Test Summary
[task 2025-02-27T03:01:50.994Z] 03:01:50 INFO - Passed: 48
[task 2025-02-27T03:01:50.994Z] 03:01:50 INFO - Failed: 3
[task 2025-02-27T03:01:50.994Z] 03:01:50 INFO - Todo: 0
[task 2025-02-27T03:01:50.995Z] 03:01:50 INFO - Mode: e10s
[task 2025-02-27T03:01:50.995Z] 03:01:50 INFO - *** End BrowserChrome Test Results ***
[task 2025-02-27T03:01:51.007Z] 03:01:51 INFO - GECKO(1082) | Exiting due to channel error.
[task 2025-02-27T03:01:51.007Z] 03:01:51 INFO - GECKO(1082) | Exiting due to channel error.
[task 2025-02-27T03:01:51.008Z] 03:01:51 INFO - GECKO(1082) | Exiting due to channel error.
[task 2025-02-27T03:01:51.008Z] 03:01:51 INFO - GECKO(1082) | Exiting due to channel error.
[task 2025-02-27T03:01:51.008Z] 03:01:51 INFO - GECKO(1082) | Exiting due to channel error.
[task 2025-02-27T03:01:51.009Z] 03:01:51 INFO - GECKO(1082) | Exiting due to channel error.
[task 2025-02-27T03:01:51.009Z] 03:01:51 INFO - GECKO(1082) | Exiting due to channel error.
[task 2025-02-27T03:01:51.043Z] 03:01:51 INFO - TEST-INFO | Main app process: exit 0
[task 2025-02-27T03:01:51.044Z] 03:01:51 INFO - TEST-UNEXPECTED-FAIL | browser/components/profiles/tests/browser/browser_test_last_tab.js | Application shut down (without crashing) in the middle of a test!
[task 2025-02-27T03:01:51.044Z] 03:01:51 INFO - TEST-INFO took 46393ms
[task 2025-02-27T03:01:51.044Z] 03:01:51 INFO - runtests.py | Application ran for: 0:01:03.204042
[task 2025-02-27T03:01:51.045Z] 03:01:51 INFO - zombiecheck | Reading PID log: /tmp/tmpphvd1r8dpidlog
[task 2025-02-27T03:01:51.045Z] 03:01:51 INFO - ==> process 1082 launched child process 1157
[task 2025-02-27T03:01:51.046Z] 03:01:51 INFO - zombiecheck | Checking for orphan process with PID: 1157
[task 2025-02-27T03:01:51.046Z] 03:01:51 INFO - Stopping web server
[task 2025-02-27T03:01:51.050Z] 03:01:51 INFO - Server shut down.
[task 2025-02-27T03:01:51.051Z] 03:01:51 INFO - Web server killed.
[task 2025-02-27T03:01:51.051Z] 03:01:51 INFO - Stopping web socket server
[task 2025-02-27T03:01:51.052Z] 03:01:51 INFO - Stopping ssltunnel
[task 2025-02-27T03:01:51.052Z] 03:01:51 INFO - Stopping gst for v4l2loopback
[task 2025-02-27T03:01:51.053Z] 03:01:51 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2025-02-27T03:01:51.053Z] 03:01:51 INFO - runtests.py | Running tests: end.
[task 2025-02-27T03:01:51.093Z] 03:01:51 INFO - Buffered messages finished
[task 2025-02-27T03:01:51.093Z] 03:01:51 INFO - TEST-INFO | checking window state
[task 2025-02-27T03:01:51.094Z] 03:01:51 INFO - Browser Chrome Test Summary
[task 2025-02-27T03:01:51.094Z] 03:01:51 INFO - Passed: 48
[task 2025-02-27T03:01:51.094Z] 03:01:51 INFO - Failed: 3
[task 2025-02-27T03:01:51.095Z] 03:01:51 INFO - Todo: 0
[task 2025-02-27T03:01:51.095Z] 03:01:51 INFO - Mode: e10s
[task 2025-02-27T03:01:51.095Z] 03:01:51 INFO - *** End BrowserChrome Test Results ***
[task 2025-02-27T03:01:51.096Z] 03:01:51 INFO - Buffered messages finished
[task 2025-02-27T03:01:51.096Z] 03:01:51 INFO - SUITE-END | took 63s
[task 2025-02-27T03:01:51.097Z] 03:01:51 INFO - SUITE-START | Running 1 tests
[task 2025-02-27T03:01:51.098Z] 03:01:51 INFO - :::
[task 2025-02-27T03:01:51.098Z] 03:01:51 INFO - ::: Test verification summary for:
[task 2025-02-27T03:01:51.099Z] 03:01:51 INFO - :::
[task 2025-02-27T03:01:51.099Z] 03:01:51 INFO - ::: browser/components/profiles/tests/browser/browser_test_last_tab.js
[task 2025-02-27T03:01:51.099Z] 03:01:51 INFO - :::
[task 2025-02-27T03:01:51.100Z] 03:01:51 INFO - ::: 1. Run each test 10 times in one browser. : FAIL
[task 2025-02-27T03:01:51.101Z] 03:01:51 INFO - ::: 2. Run each test 5 times in a new browser each time. : not run / incomplete
[task 2025-02-27T03:01:51.101Z] 03:01:51 INFO - ::: 3. Run each test 10 times in one browser, in chaos mode. : not run / incomplete
[task 2025-02-27T03:01:51.101Z] 03:01:51 INFO - ::: 4. Run each test 5 times in a new browser each time, in chaos mode. : not run / incomplete
[task 2025-02-27T03:01:51.102Z] 03:01:51 INFO - :::
[task 2025-02-27T03:01:51.102Z] 03:01:51 INFO - ::: Test verification FAILED!
[task 2025-02-27T03:01:51.102Z] 03:01:51 INFO - :::
[task 2025-02-27T03:01:51.102Z] 03:01:51 INFO - Buffered messages finished
[task 2025-02-27T03:01:51.103Z] 03:01:51 INFO - SUITE-END | took 0s
[task 2025-02-27T03:01:51.126Z] 03:01:51 INFO - Return code: 0
[task 2025-02-27T03:01:51.126Z] 03:01:51 WARNING - Got 4 unexpected statuses
[task 2025-02-27T03:01:51.126Z] 03:01:51 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>8/<em class="testfail">4</em>/0
[task 2025-02-27T03:01:51.126Z] 03:01:51 WARNING - setting return code to 1
[task 2025-02-27T03:01:51.126Z] 03:01:51 WARNING - TinderboxPrint: Per-test run of .../browser/browser_test_last_tab.js<br/>: WARNING
[task 2025-02-27T03:01:51.126Z] 03:01:51 INFO - Per-test suites: {}
[task 2025-02-27T03:01:51.126Z] 03:01:51 INFO - Per-test suites: {}
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Running post-action listener: _package_coverage_data
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Running post-action listener: _resource_record_post_action
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Running post-action listener: process_java_coverage_data
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - [mozharness: 2025-02-27 03:01:51.127235Z] Finished run-tests step (success)
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - [mozharness: 2025-02-27 03:01:51.127286Z] Running uninstall step.
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Running pre-action listener: _resource_record_pre_action
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Running main action method: uninstall
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Skipping uninstall for non-MSIX test
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Running post-action listener: _resource_record_post_action
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - [mozharness: 2025-02-27 03:01:51.127501Z] Finished uninstall step (success)
[task 2025-02-27T03:01:51.127Z] 03:01:51 INFO - Running post-run listener: _resource_record_post_run
[task 2025-02-27T03:01:51.199Z] 03:01:51 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2025-02-27T03:01:51.201Z] 03:01:51 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": ".overall", "extraOptions": ["e10s", "taskcluster-projects/887720501152/machineTypes/c2-standard-4"], "subtests": [{"name": "cpu_percent", "value": 21.10620567375885}, {"name": "io_write_bytes", "value": 481439744}, {"name": "io.read_bytes", "value": 0}, {"name": "io_write_time", "value": 399796}, {"name": "io_read_time", "value": 0}]}, {"name": ".start-pulseaudio", "subtests": [{"name": "time", "value": 0.0211561599999186}, {"name": "cpu_percent", "value": 0}]}, {"name": ".install", "subtests": [{"name": "time", "value": 5.720319052999912}, {"name": "cpu_percent", "value": 25.454910714285717}]}, {"name": ".stage-files", "subtests": [{"name": "time", "value": 0.0004614429999492131}, {"name": "cpu_percent", "value": 0}]}, {"name": ".run-tests", "subtests": [{"name": "time", "value": 64.82203475300003}, {"name": "cpu_percent", "value": 20.696406491499225}]}, {"name": ".uninstall", "subtests": [{"name": "time", "value": 0.0001386429999001848}, {"name": "cpu_percent", "value": 0}]}]}
[task 2025-02-27T03:01:51.201Z] 03:01:51 INFO - Total resource usage - Wall time: 71s; CPU: Can't collect data; Read bytes: 0; Write bytes: 481439744; Read time: 0; Write time: 399796
[task 2025-02-27T03:01:51.201Z] 03:01:51 INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2025-02-27T03:01:51.201Z] 03:01:51 INFO - TinderboxPrint: I/O write bytes / time<br/>481,439,744 / 399,796
[task 2025-02-27T03:01:51.201Z] 03:01:51 INFO - TinderboxPrint: CPU idle<br/>218.1 (77.7%)
[task 2025-02-27T03:01:51.202Z] 03:01:51 INFO - TinderboxPrint: CPU iowait<br/>3.9 (1.4%)
[task 2025-02-27T03:01:51.202Z] 03:01:51 INFO - TinderboxPrint: CPU system<br/>4.2 (1.5%)
[task 2025-02-27T03:01:51.202Z] 03:01:51 INFO - TinderboxPrint: CPU user<br/>54.5 (19.4%)
[task 2025-02-27T03:01:51.202Z] 03:01:51 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2025-02-27T03:01:51.202Z] 03:01:51 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2025-02-27T03:01:51.202Z] 03:01:51 INFO - install - Wall time: 6s; CPU: 25%; Read bytes: 0; Write bytes: 16740352; Read time: 0; Write time: 2508
[task 2025-02-27T03:01:51.203Z] 03:01:51 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2025-02-27T03:01:51.206Z] 03:01:51 INFO - run-tests - Wall time: 65s; CPU: 21%; Read bytes: 0; Write bytes: 464699392; Read time: 0; Write time: 397288
[task 2025-02-27T03:01:51.207Z] 03:01:51 INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2025-02-27T03:01:51.326Z] 03:01:51 WARNING - returning nonzero exit status 1
Description
•