Closed
Bug 1934753
Opened 2 months ago
Closed 2 months ago
Intermittent [tier 2] raptor-browsertime Critical: ScriptTimeoutError: Timed out after 72000 ms
Categories
(Testing :: Raptor, defect, P5)
Testing
Raptor
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=485082517&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fM-5uT7KRCmideluEsVRUQ/runs/0/artifacts/public/logs/live_backing.log
[task 2024-12-03T02:21:14.553Z] 02:21:14 INFO - raptor-perftest Info: starting test: connect
[task 2024-12-03T02:21:14.554Z] 02:21:14 INFO - raptor-browsertime Info: test: {'here': 'C:\\task_173319183380205\\build\\tests\\raptor\\raptor\\tests\\custom', 'alert_on': ['ContentfulSpeedIndex', 'FirstVisualChange', 'PerceptualSpeedIndex', 'SpeedIndex', 'fcp', 'loadtime'], 'alert_change_type': 'absolute', 'alert_threshold': '10.0', 'apps': 'firefox', 'cold': True, 'lower_is_better': True, 'owner': 'Network Team', 'page_cycles': 1, 'page_timeout': 72000.0, 'type': 'pageload', 'unit': 'ms', 'use_live_sites': 'true', 'browser_cycles': '3', 'test_script': 'speculative-connect.js', 'test_url': 'None', 'custom_data': 'true', 'name': 'connect', 'manifest': 'C:\\task_173319183380205\\build\\tests\\raptor\\raptor\\tests\\custom\\browsertime-speculative.toml', 'manifest_relpath': 'tests\\custom\\browsertime-speculative.toml', 'path': 'C:\\task_173319183380205\\build\\tests\\raptor\\raptor\\tests\\custom\\connect', 'relpath': 'tests\\custom\\connect', 'ancestor_manifest': 'raptor.toml', 'expected': 'pass', 'expected_browser_cycles': 3, 'browser_cycle': 1, 'playback': None, 'measure': ['fnbpaint', 'fcp', 'loadtime', 'ContentfulSpeedIndex', 'PerceptualSpeedIndex', 'SpeedIndex', 'FirstVisualChange', 'LastVisualChange', 'largestContentfulPaint']}
[task 2024-12-03T02:21:14.554Z] 02:21:14 INFO - raptor-browsertime-desktop Info: binary_path: C:\task_173319183380205\build\application\firefox\firefox.exe
[task 2024-12-03T02:21:14.554Z] 02:21:14 INFO - raptor-browsertime Info: Using Firefox Window Recorder for videos
[task 2024-12-03T02:21:14.554Z] 02:21:14 INFO - raptor-browsertime Info: timeout (s): 72000
[task 2024-12-03T02:21:14.554Z] 02:21:14 INFO - raptor-browsertime Info: browsertime cwd: C:\task_173319183380205\build
[task 2024-12-03T02:21:14.555Z] 02:21:14 INFO - raptor-browsertime Info: browsertime cmd: C:/task_173319183380205/fetches/node/node.exe C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/bin/browsertime.js --firefox.geckodriverPath C:/task_173319183380205/fetches/geckodriver.exe C:\task_173319183380205\build\tests\raptor\raptor\browsertime\..\..\browsertime\speculative-connect.js --firefox.noDefaultPrefs --browsertime.page_cycle_delay 1000 --skipHar --pageLoadStrategy none --webdriverPageload true --firefox.disableBrowsertimeExtension true --pageCompleteCheckStartWait 5000 --pageCompleteCheckPollTimeout 1000 --beforePageCompleteWaitTime 2000 --timeouts.pageLoad 72000 --timeouts.script 72000 --browsertime.page_cycles 1 --pageCompleteWaitTime 5000 --browsertime.url None --browsertime.post_startup_delay 1000 --iterations 3 --browsertime.chimera false --browsertime.test_bytecode_cache false --firefox.perfStats false --browsertime.moz_fetch_dir C:/task_173319183380205/fetches --browsertime.expose_profiler false --browsertime.commands --viewPort 1280x1024 --browser firefox --firefox.binaryPath C:\task_173319183380205\build\application\firefox\firefox.exe --resultDir C:\task_173319183380205\build\blobber_upload_dir\browsertime-results\connect --firefox.profileTemplate C:\Users\task_173319183380205\AppData\Local\Temp\tmpe9wf6qfp\profile --video true --visualMetrics true --visualMetricsContentful true --visualMetricsPerceptual true --visualMetricsPortable true --videoParams.keepOriginalVideo true --firefox.windowRecorder true --browsertime.testName connect --browsertime.liveSite False --browsertime.loginRequired False
[task 2024-12-03T02:21:14.555Z] 02:21:14 INFO - raptor-browsertime Info: browsertime_ffmpeg: C:/task_173319183380205/fetches/ffmpeg-4.4.1-full_build/bin/ffmpeg.exe
[task 2024-12-03T02:21:14.555Z] 02:21:14 INFO - raptor-browsertime Info: PATH: C:\task_173319183380205\fetches\ffmpeg-4.4.1-full_build\bin;C:\task_173319183380205\build\venv\Scripts;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Windows\System32\OpenSSH\;C:\ProgramData\chocolatey\bin;C:\Windows\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\Program Files\git\bin;C:\Program Files\Puppet Labs\Puppet\bin;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\;C:\Program Files (x86)\GNU\GnuPG\pub;C:\Program Files\Mercurial\;C:\mozilla-build\bin;C:\mozilla-build\kdiff3;C:\mozilla-build\msys2;C:\mozilla-build\python3;C:\mozilla-build\msys2\usr\bin;C:\Users\task_173319183380205\AppData\Local\Microsoft\WindowsApps
[task 2024-12-03T02:21:14.555Z] 02:21:14 INFO - raptor-browsertime Info: Calling browsertime with proc_timeout=459, and output_timeout=120
[task 2024-12-03T02:21:15.758Z] 02:21:15 INFO - raptor-browsertime Info: Running tests using Firefox - 3 iteration(s)
[task 2024-12-03T02:21:15.758Z] 02:21:15 INFO - raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2024-12-03T02:21:17.933Z] 02:21:17 INFO - raptor-browsertime Info: Starting a pageload for which we will first make a speculative connection to the host
[task 2024-12-03T02:21:17.933Z] 02:21:17 INFO - raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2024-12-03T02:21:24.977Z] 02:21:24 INFO - raptor-browsertime Info: Start to measure
[task 2024-12-03T02:21:24.978Z] 02:21:24 INFO - raptor-browsertime Info: Start firefox window recorder.
[task 2024-12-03T02:21:25.814Z] 02:21:25 INFO - raptor-browsertime Info: Navigating to url https://en.wikipedia.org/wiki/Barack_Obama iteration 1
[task 2024-12-03T02:21:31.860Z] 02:21:31 INFO - raptor-browsertime Info: Stop firefox window recorder.
[task 2024-12-03T02:22:47.923Z] 02:22:47 ERROR - raptor-browsertime Error: Browsertime failed to run
[task 2024-12-03T02:22:47.923Z] 02:22:47 INFO - raptor-browsertime Info: Mark run as failure with message: Timed out after 72000 ms
[task 2024-12-03T02:22:47.923Z] 02:22:47 ERROR - raptor-browsertime Error: Browsertime failed to run
[task 2024-12-03T02:22:47.924Z] 02:22:47 INFO - raptor-browsertime Info: at Object.throwDecodedError (C:\task_173319183380205\fetches\browsertime\node_modules\selenium-webdriver\lib\error.js:521:15)
[task 2024-12-03T02:22:47.924Z] 02:22:47 INFO - raptor-browsertime Info: at parseHttpResponse (C:\task_173319183380205\fetches\browsertime\node_modules\selenium-webdriver\lib\http.js:514:13)
[task 2024-12-03T02:22:47.924Z] 02:22:47 INFO - raptor-browsertime Info: at Executor.execute (C:\task_173319183380205\fetches\browsertime\node_modules\selenium-webdriver\lib\http.js:446:28)
[task 2024-12-03T02:22:47.925Z] 02:22:47 INFO - raptor-browsertime Info: at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[task 2024-12-03T02:22:47.925Z] 02:22:47 INFO - raptor-browsertime Info: at async Driver.execute (C:\task_173319183380205\fetches\browsertime\node_modules\selenium-webdriver\lib\webdriver.js:744:17)
[task 2024-12-03T02:22:47.925Z] 02:22:47 INFO - raptor-browsertime Info: at async SeleniumRunner.runPrivilegedAsyncScript (file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/lib/core/seleniumRunner.js:495:22)
[task 2024-12-03T02:22:47.925Z] 02:22:47 INFO - raptor-browsertime Info: at async FirefoxWindowRecorder.stop (file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/lib/video/screenRecording/firefox/firefoxWindowRecorder.js:177:5)
[task 2024-12-03T02:22:47.926Z] 02:22:47 INFO - raptor-browsertime Info: at async Measure._stopVideo (file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/lib/core/engine/command/measure.js:177:7)
[task 2024-12-03T02:22:47.926Z] 02:22:47 INFO - raptor-browsertime Info: at async Measure.stop (file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/lib/core/engine/command/measure.js:434:5)
[task 2024-12-03T02:22:47.926Z] 02:22:47 INFO - raptor-browsertime Info: at async object.<computed> [as stop] (C:\task_173319183380205\build\tests\raptor\browsertime\utils\profiling.js:99:14)
[task 2024-12-03T02:22:47.927Z] 02:22:47 INFO - raptor-browsertime Info: at async C:\task_173319183380205\build\tests\raptor\browsertime\speculative-connect.js:35:5
[task 2024-12-03T02:22:47.927Z] 02:22:47 INFO - raptor-browsertime Info: at async wrappedTest (C:\task_173319183380205\build\tests\raptor\browsertime\utils\profiling.js:269:14)
[task 2024-12-03T02:22:47.927Z] 02:22:47 INFO - raptor-browsertime Info: at async file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/lib/core/engine/run.js:4:7
[task 2024-12-03T02:22:47.927Z] 02:22:47 INFO - raptor-browsertime Info: at async Iteration.run (file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/lib/core/engine/iteration.js:162:9)
[task 2024-12-03T02:22:47.927Z] 02:22:47 INFO - raptor-browsertime Info: at async Engine.runByScript (file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/lib/core/engine/index.js:308:20)
[task 2024-12-03T02:22:47.927Z] 02:22:47 INFO - raptor-browsertime Info: at async run (file:///C:/task_173319183380205/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:104:22)
[task 2024-12-03T02:22:48.015Z] 02:22:48 INFO - TEST-INFO | screenshot: exit 0
[task 2024-12-03T02:22:48.015Z] 02:22:48 CRITICAL - raptor-browsertime Critical: ScriptTimeoutError: Timed out after 72000 ms
[task 2024-12-03T02:22:48.016Z] 02:22:48 INFO - raptor-perftest Info: Removing temporary directory: C:\Users\task_173319183380205\AppData\Local\Temp\tmpe9wf6qfp
[task 2024-12-03T02:22:48.036Z] 02:22:48 ERROR - Traceback (most recent call last):
[task 2024-12-03T02:22:48.037Z] 02:22:48 INFO - File "C:\task_173319183380205\build\tests\raptor\raptor\raptor.py", line 189, in <module>
[task 2024-12-03T02:22:48.038Z] 02:22:48 INFO - main()
[task 2024-12-03T02:22:48.038Z] 02:22:48 INFO - File "C:\task_173319183380205\build\tests\raptor\raptor\raptor.py", line 138, in main
[task 2024-12-03T02:22:48.038Z] 02:22:48 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2024-12-03T02:22:48.039Z] 02:22:48 INFO - ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2024-12-03T02:22:48.039Z] 02:22:48 INFO - File "C:\task_173319183380205\build\tests\raptor\raptor\perftest.py", line 501, in run_tests
[task 2024-12-03T02:22:48.039Z] 02:22:48 INFO - self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2024-12-03T02:22:48.039Z] 02:22:48 INFO - File "C:\task_173319183380205\build\tests\raptor\raptor\browsertime\base.py", line 1099, in run_test
[task 2024-12-03T02:22:48.040Z] 02:22:48 INFO - raise Exception(self.browsertime_failure)
[task 2024-12-03T02:22:48.040Z] 02:22:48 INFO - Exception: ScriptTimeoutError: Timed out after 72000 ms
[task 2024-12-03T02:22:48.116Z] 02:22:48 INFO - Return code: 1
[task 2024-12-03T02:22:48.116Z] 02:22:48 WARNING - setting return code to 1
[task 2024-12-03T02:22:48.116Z] 02:22:48 INFO - Copying Raptor results to upload dir:
[task 2024-12-03T02:22:48.130Z] 02:22:48 INFO - C:\task_173319183380205\build\blobber_upload_dir\perfherder-data.json
[task 2024-12-03T02:22:48.130Z] 02:22:48 INFO - Copying raptor results from C:\task_173319183380205\build\raptor.json to C:\task_173319183380205\build\blobber_upload_dir\perfherder-data.json
[task 2024-12-03T02:22:48.130Z] 02:22:48 CRITICAL - Error copying results C:\task_173319183380205\build\raptor.json to upload dir C:\task_173319183380205\build\blobber_upload_dir\perfherder-data.json
[task 2024-12-03T02:22:48.130Z] 02:22:48 INFO - [Errno 2] No such file or directory: 'C:\\task_173319183380205\\build\\raptor.json'
[task 2024-12-03T02:22:48.130Z] 02:22:48 INFO - Running post-action listener: _package_coverage_data
[task 2024-12-03T02:22:48.130Z] 02:22:48 INFO - Running post-action listener: _resource_record_post_action
[task 2024-12-03T02:22:48.131Z] 02:22:48 INFO - Running post-action listener: process_java_coverage_data
[task 2024-12-03T02:22:48.131Z] 02:22:48 INFO - Running post-action listener: stop_device
[task 2024-12-03T02:22:48.131Z] 02:22:48 INFO - [mozharness: 2024-12-03 02:22:48.131352Z] Finished run-tests step (success)
[task 2024-12-03T02:22:48.131Z] 02:22:48 INFO - Running post-run listener: _resource_record_post_run
[task 2024-12-03T02:22:48.258Z] 02:22:48 INFO - Total resource usage - Wall time: 136s; CPU: 4%; Read bytes: 1243086848; Write bytes: 852369408; Read time: 70; Write time: 12
[task 2024-12-03T02:22:48.258Z] 02:22:48 INFO - TinderboxPrint: CPU usage<br/>4.2%
[task 2024-12-03T02:22:48.258Z] 02:22:48 INFO - TinderboxPrint: I/O read bytes / time<br/>1,243,086,848 / 70
[task 2024-12-03T02:22:48.258Z] 02:22:48 INFO - TinderboxPrint: I/O write bytes / time<br/>852,369,408 / 12
[task 2024-12-03T02:22:48.258Z] 02:22:48 INFO - TinderboxPrint: CPU idle<br/>2,074.0 (95.8%)
[task 2024-12-03T02:22:48.258Z] 02:22:48 INFO - TinderboxPrint: CPU system<br/>28.2 (1.3%)
[task 2024-12-03T02:22:48.258Z] 02:22:48 INFO - TinderboxPrint: CPU user<br/>62.6 (2.9%)
[task 2024-12-03T02:22:48.264Z] 02:22:48 INFO - install-chromium-distribution - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-12-03T02:22:48.264Z] 02:22:48 INFO - install - Wall time: 2s; CPU: 16%; Read bytes: 3140096; Write bytes: 96014336; Read time: 0; Write time: 0
[task 2024-12-03T02:22:48.271Z] 02:22:48 INFO - run-tests - Wall time: 134s; CPU: 4%; Read bytes: 1239946752; Write bytes: 756355072; Read time: 70; Write time: 12
[task 2024-12-03T02:22:48.555Z] 02:22:48 WARNING - returning nonzero exit status 1
[taskcluster 2024-12-03T02:22:48.617Z] Exit Code: 1
[taskcluster 2024-12-03T02:22:48.617Z] User Time: 0s
[taskcluster 2024-12-03T02:22:48.617Z] Kernel Time: 15.625ms
[taskcluster 2024-12-03T02:22:48.617Z] Wall Time: 3m17.4137359s
[taskcluster 2024-12-03T02:22:48.617Z] Result: FAILED
[taskcluster 2024-12-03T02:22:48.618Z] === Task Finished ===
[taskcluster 2024-12-03T02:22:48.619Z] Task Duration: 3m17.4185398s
[taskcluster 2024-12-03T02:22:48.967Z] Uploading artifact public/test_info/mozilla-test-fail-screenshot_dn6kba9_.png from file C:\task_173319183380205\build\blobber_upload_dir\mozilla-test-fail-screenshot_dn6kba9_.png with content encoding "identity", mime type "image/png" and expiry 2025-12-02T23:09:38.023Z
[taskcluster 2024-12-03T02:22:48.967Z] Uploading artifact public/test_info/resource-usage.json from file C:\task_173319183380205\build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-12-02T23:09:38.023Z
[taskcluster 2024-12-03T02:22:48.968Z] Uploading artifact public/logs/localconfig.json from file C:\task_173319183380205\logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2025-12-02T23:09:38.023Z
[taskcluster 2024-12-03T02:22:48.971Z] Uploading artifact public/test_info/profile_resource-usage.json from file C:\task_173319183380205\build\blobber_upload_dir\profile_resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-12-02T23:09:38.023Z
[taskcluster 2024-12-03T02:22:49.351Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2025-12-02T23:09:38.023Z
[taskcluster:error] exit status 1
Comment hidden (Intermittent Failures Robot) |
Comment 2•2 months ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•