Open Bug 2049556 Opened 29 days ago Updated 9 days ago

TV | browser/components/aiwindow/ui/test/browser/browser_aiwindow_ask_button.js | application timed out after 740.0 seconds with no output - single tracking bug

Categories

(Core :: Machine Learning: Frontend, defect, P5)

Product:
Core
Component:
Machine Learning: Frontend
Type:
defect

Tracking

()

Tracking Flags:
Tracking Status
firefox-esr140 --- unaffected
firefox152 --- unaffected
firefox153 --- unaffected
firefox154 --- affected

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, test-verify-fail)

Filed by: asilaghi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=574404940&repo=autoland&task=QGQuJjICQo6Jk1TMAUV7xQ.0
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QGQuJjICQo6Jk1TMAUV7xQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/default/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QGQuJjICQo6Jk1TMAUV7xQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - TEST-PASS | browser/components/aiwindow/ui/test/browser/browser_aiwindow_ask_button.js | test_classic_window - Ask button is not visible in the toolbar for classic window - true == true
[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - Buffered messages logged at 02:40:58
[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - Leaving test test_classic_window
[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - Entering test test_ask_button_immersive_view
[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - Opening new AI Window
[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - Buffered messages finished
[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - TEST-UNEXPECTED-TIMEOUT | browser/components/aiwindow/ui/test/browser/browser_aiwindow_ask_button.js | application timed out after 740.0 seconds with no output
[task 2026-06-23T02:53:25.797+00:00] 02:53:25     INFO - TEST-INFO took 761905ms
[task 2026-06-23T02:53:25.798+00:00] 02:53:25     INFO - Buffered messages finished
[task 2026-06-23T02:53:25.798+00:00] 02:53:25  WARNING - Force-terminating active process(es).
[task 2026-06-23T02:53:25.798+00:00] 02:53:25  WARNING - profiler Attempting to start the profiler to help with diagnosing the hang.
[task 2026-06-23T02:53:25.798+00:00] 02:53:25     INFO - profiler Sending SIGUSR1 to pid 1681 start the profiler.
[task 2026-06-23T02:53:25.798+00:00] 02:53:25     INFO - profiler Waiting 10s to capture a profile...
[task 2026-06-23T02:53:35.793+00:00] 02:53:35     INFO - profiler Sending SIGUSR2 to pid 1681 stop the profiler.
[task 2026-06-23T02:53:35.793+00:00] 02:53:35     INFO - profiler Wait 10s for Firefox to write the profile to disk.
[task 2026-06-23T02:53:45.802+00:00] 02:53:45     INFO - profiler Symbolicating profile in /opt/worker/tasks/cltbld/build/blobber_upload_dir
[task 2026-06-23T02:53:45.802+00:00] 02:53:45     INFO - profiler Looking inside symbols dir: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/X66QO4ORQA6o4gLvzE3oaA/artifacts/public/build/target.crashreporter-symbols.zip)
[task 2026-06-23T02:53:45.802+00:00] 02:53:45     INFO - profiler Symbolicating profile: /opt/worker/tasks/cltbld/build/blobber_upload_dir/profile_0_1681.json
[task 2026-06-23T02:53:45.803+00:00] 02:53:45     INFO - profiler Symbolicating the performance profile... This could take a couple of minutes.
[task 2026-06-23T02:53:45.880+00:00] 02:53:45  WARNING - profiler /opt/worker/tasks/cltbld/fetches/profiler-node-tools/profiler-edit.js does not exist.
[task 2026-06-23T02:53:45.881+00:00] 02:53:45     INFO - profiler Symbolication dependencies not available, using fallback symbolication.
[task 2026-06-23T02:53:46.295+00:00] 02:53:46     INFO - Determining child pids from psutil...
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - [1689, 1692, 1693, 1695, 1702, 1705, 1715]
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1689
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1692
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1693
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1695
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1702
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1703
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1704
[task 2026-06-23T02:53:46.298+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1705
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1715
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1759
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1767
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1792
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1801
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1843
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1847
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1927
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1936
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1960
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - ==> process 1681 launched child process 1969
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - Found child pids: {1792, 1927, 1801, 1936, 1689, 1692, 1693, 1695, 1702, 1703, 1704, 1705, 1960, 1969, 1715, 1843, 1847, 1759, 1767}
[task 2026-06-23T02:53:46.299+00:00] 02:53:46     INFO - Failed to get child procs
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Killing process: 1792
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Not taking screenshot here: screenshot will be taken on retry if the test still fails
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Can't trigger Breakpad, just killing process
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Error: Failed to kill process 1792: process PID not found (pid=1792)
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Killing process: 1927
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Not taking screenshot here: screenshot will be taken on retry if the test still fails
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Can't trigger Breakpad, just killing process
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Error: Failed to kill process 1927: process PID not found (pid=1927)
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Killing process: 1801
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Not taking screenshot here: screenshot will be taken on retry if the test still fails
[task 2026-06-23T02:53:46.300+00:00] 02:53:46     INFO - Can't trigger Breakpad, just killing process
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Error: Failed to kill process 1801: process PID not found (pid=1801)
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Killing process: 1936
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Not taking screenshot here: screenshot will be taken on retry if the test still fails
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Can't trigger Breakpad, just killing process
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Error: Failed to kill process 1936: process PID not found (pid=1936)
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Killing process: 1689
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Not taking screenshot here: screenshot will be taken on retry if the test still fails
[task 2026-06-23T02:53:46.301+00:00] 02:53:46     INFO - Can't trigger Breakpad, just killing process
[task 2026-06-23T02:54:10.244+00:00] 02:54:10     INFO - psutil found pid 1689 dead
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Killing process: 1692
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Not taking screenshot here: screenshot will be taken on retry if the test still fails
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Can't trigger Breakpad, just killing process
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Error: Failed to kill process 1692: process PID not found (pid=1692)
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Killing process: 1693
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Not taking screenshot here: screenshot will be taken on retry if the test still fails
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Can't trigger Breakpad, just killing process
[task 2026-06-23T02:54:10.245+00:00] 02:54:10     INFO - Error: Failed to kill process 1693: process PID not found (pid=1693)
[task 2026-06-23T02:54:10.246+00:00] 02:54:10     INFO - Killing process: 1695
<...>
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - Running post-action listener: process_java_coverage_data
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - [mozharness: 2026-06-23 03:49:16.847619Z] Finished run-tests step (success)
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - [mozharness: 2026-06-23 03:49:16.847631Z] Running uninstall step.
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - Running pre-action listener: _resource_record_pre_action
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - Running main action method: uninstall
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - Skipping uninstall for non-MSIX test
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - Running post-action listener: _resource_record_post_action
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - [mozharness: 2026-06-23 03:49:16.847684Z] Finished uninstall step (success)
[task 2026-06-23T03:49:16.847+00:00] 03:49:16     INFO - Running post-run listener: _resource_record_post_run
[task 2026-06-23T03:49:16.977+00:00] 03:49:16     INFO - instance_metadata.json not found; unable to determine instance type
[task 2026-06-23T03:49:17.012+00:00] 03:49:17     INFO - Validating Perfherder data against /opt/worker/tasks/cltbld/mozharness/external_tools/performance-artifact-schema.json
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": ".overall", "extraOptions": ["e10s", "buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 13.269099374659865}, {"name": "io_write_bytes", "value": 2937307136}, {"name": "io.read_bytes", "value": 2990874624}, {"name": "io_write_time", "value": 3069}, {"name": "io_read_time", "value": 65166}]}, {"name": ".start-pulseaudio", "subtests": [{"name": "time", "value": 5.1542000008453215e-05}, {"name": "cpu_percent", "value": 0}]}, {"name": ".unlock-keyring", "subtests": [{"name": "time", "value": 2.5250000007304152e-05}, {"name": "cpu_percent", "value": 0}]}, {"name": ".install", "subtests": [{"name": "time", "value": 10.814330499999997}, {"name": "cpu_percent", "value": 11.103457943925235}]}, {"name": ".stage-files", "subtests": [{"name": "time", "value": 0.00012041600000145536}, {"name": "cpu_percent", "value": 0}]}, {"name": ".run-tests", "subtests": [{"name": "time", "value": 4402.187478208}, {"name": "cpu_percent", "value": 13.273923412373657}]}, {"name": ".uninstall", "subtests": [{"name": "time", "value": 2.6666999474400654e-05}, {"name": "cpu_percent", "value": 0}]}]}
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - Total resource usage - Wall time: 4413s; CPU: Can't collect data; Read bytes: 2990874624; Write bytes: 2937307136; Read time: 65166; Write time: 3069
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - TinderboxPrint: I/O read bytes / time<br/>2,990,874,624 / 65,166
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - TinderboxPrint: I/O write bytes / time<br/>2,937,307,136 / 3,069
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - TinderboxPrint: CPU idle<br/>38,168.5 (86.6%)
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - TinderboxPrint: CPU system<br/>765.3 (1.7%)
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - TinderboxPrint: CPU user<br/>5,125.8 (11.6%)
[task 2026-06-23T03:49:17.013+00:00] 03:49:17     INFO - TinderboxPrint: Swap in / out<br/>1,143,996,416 / 81,920
[task 2026-06-23T03:49:17.017+00:00] 03:49:17     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2026-06-23T03:49:17.021+00:00] 03:49:17     INFO - unlock-keyring - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2026-06-23T03:49:17.025+00:00] 03:49:17     INFO - install - Wall time: 11s; CPU: 11%; Read bytes: 366132224; Write bytes: 367902720; Read time: 9833; Write time: 381
[task 2026-06-23T03:49:17.029+00:00] 03:49:17     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2026-06-23T03:49:17.127+00:00] 03:49:17     INFO - run-tests - Wall time: 4402s; CPU: 13%; Read bytes: 2985070592; Write bytes: 2569375744; Read time: 64968; Write time: 2688
[task 2026-06-23T03:49:17.135+00:00] 03:49:17     INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2026-06-23T03:49:18.481+00:00] 03:49:18  WARNING - returning nonzero exit status 1
[taskcluster 2026-06-23T03:49:18.666Z]                        Exit Code: 1
[taskcluster 2026-06-23T03:49:18.666Z]                        User Time: 1h17m37.599859s
[taskcluster 2026-06-23T03:49:18.666Z]                      Kernel Time: 1m52.298946s
[taskcluster 2026-06-23T03:49:18.666Z]                        Wall Time: 1h14m13.257091s
[taskcluster 2026-06-23T03:49:18.666Z]  Average Available System Memory: 7.21 GiB
[taskcluster 2026-06-23T03:49:18.666Z]       Average System Memory Used: 8.79 GiB
[taskcluster 2026-06-23T03:49:18.666Z]          Peak System Memory Used: 9.20 GiB
[taskcluster 2026-06-23T03:49:18.666Z]              Total System Memory: 16.00 GiB
[taskcluster 2026-06-23T03:49:18.666Z]                           Result: FAILED
[taskcluster 2026-06-23T03:49:18.666Z] === Task Finished ===
[taskcluster 2026-06-23T03:49:18.666Z] Task Duration: 1h14m13.76787s
[taskcluster 2026-06-23T03:49:20.162Z] [mounts] Preserving cache: Moving "/opt/worker/tasks/cltbld/.task-cache/pip" to "/opt/worker/cache/KcXF3obGRku7Y9caEmDBXg"
[taskcluster 2026-06-23T03:49:20.163Z] [mounts] Preserving cache: Moving "/opt/worker/tasks/cltbld/.task-cache/uv" to "/opt/worker/cache/M03FhOu6RXG03uPDGJaJ-g"
[taskcluster:error] <nil>

:jlewis, since you are the author of the regressor, bug 2044164, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(jlewis)

Set release status flags based on info from the regressing bug 2044164

status-firefox152: --- → unaffected
status-firefox153: --- → unaffected
status-firefox154: --- → affected
status-firefox-esr140: --- → unaffected
You need to log in before you can comment on or make changes to this bug.