1879702 - Intermittent [tier 2] raptor-browsertime Critical: ScriptTimeoutError: Timed out after 1800000 ms

Status: REOPENED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=446787104&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BiSW4KWBThWE_o5e-M_xtQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2024-02-10T09:17:11.090Z] 09:17:11     INFO -  raptor-browsertime Info: IndexedDB write URL = https://www.example.com
[task 2024-02-10T09:17:11.090Z] 09:17:11     INFO -  raptor-browsertime Info: IndexedDB write chunk size = 1048576
[task 2024-02-10T09:17:11.091Z] 09:17:11     INFO -  raptor-browsertime Info: IndexedDB write iterations = 128
[task 2024-02-10T09:17:11.091Z] 09:17:11     INFO -  raptor-browsertime Info: IndexedDB writes in separate transactions
[task 2024-02-10T09:17:11.091Z] 09:17:11     INFO -  raptor-browsertime Info: IndexedDB write data format Blob
[task 2024-02-10T09:17:11.091Z] 09:17:11     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2024-02-10T09:17:11.092Z] 09:17:11     INFO -  raptor-browsertime Info: Navigating to url https://www.example.com iteration 1
[task 2024-02-10T09:17:18.056Z] 09:17:18     INFO -  raptor-browsertime Info: Start to measure
[taskcluster 2024-02-10T09:30:50.177Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/BiSW4KWBThWE_o5e-M_xtQ/0/on/mdc1/T-W1064-MS-622/until/1707558650.249
[task 2024-02-10T09:47:18.149Z] 09:47:18    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2024-02-10T09:47:18.150Z] 09:47:18     INFO -  raptor-browsertime Info:     at Object.throwDecodedError (C:\Users\task_1707526604\fetches\browsertime\node_modules\selenium-webdriver\lib\error.js:524:15)
[task 2024-02-10T09:47:18.150Z] 09:47:18     INFO -  raptor-browsertime Info:     at parseHttpResponse (C:\Users\task_1707526604\fetches\browsertime\node_modules\selenium-webdriver\lib\http.js:601:13)
[task 2024-02-10T09:47:18.151Z] 09:47:18     INFO -  raptor-browsertime Info:     at Executor.execute (C:\Users\task_1707526604\fetches\browsertime\node_modules\selenium-webdriver\lib\http.js:529:28)
[task 2024-02-10T09:47:18.152Z] 09:47:18     INFO -  raptor-browsertime Info:     at processTicksAndRejections (node:internal/process/task_queues:96:5)
[task 2024-02-10T09:47:18.152Z] 09:47:18     INFO -  raptor-browsertime Info:     at async Driver.execute (C:\Users\task_1707526604\fetches\browsertime\node_modules\selenium-webdriver\lib\webdriver.js:745:17)
[task 2024-02-10T09:47:18.152Z] 09:47:18     INFO -  raptor-browsertime Info:     at async module.exports (C:\Users\task_1707526604\build\tests\raptor\browsertime\indexeddb_write.js:48:25)
[task 2024-02-10T09:47:18.153Z] 09:47:18     INFO -  raptor-browsertime Info:     at async file:///C:/Users/task_1707526604/fetches/browsertime/node_modules/browsertime/lib/core/engine/run.js:4:7
[task 2024-02-10T09:47:18.154Z] 09:47:18     INFO -  raptor-browsertime Info:     at async Iteration.run (file:///C:/Users/task_1707526604/fetches/browsertime/node_modules/browsertime/lib/core/engine/iteration.js:244:9)
[task 2024-02-10T09:47:18.154Z] 09:47:18     INFO -  raptor-browsertime Info:     at async Engine.runByScript (file:///C:/Users/task_1707526604/fetches/browsertime/node_modules/browsertime/lib/core/engine/index.js:304:20)
[task 2024-02-10T09:47:18.155Z] 09:47:18     INFO -  raptor-browsertime Info:     at async run (file:///C:/Users/task_1707526604/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:104:22)
[task 2024-02-10T09:47:18.155Z] 09:47:18     INFO -  raptor-browsertime Info:     at async file:///C:/Users/task_1707526604/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:217:1
[task 2024-02-10T09:47:18.173Z] 09:47:18 CRITICAL -  raptor-browsertime Critical: ScriptTimeoutError: Timed out after 1800000 ms
[task 2024-02-10T09:47:18.174Z] 09:47:18     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2024-02-10T09:47:18.174Z] 09:47:18     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2024-02-10T09:47:18.174Z] 09:47:18     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 4400
[task 2024-02-10T09:47:18.174Z] 09:47:18     INFO -  raptor-mitmproxy Info: Sending CTRL_BREAK_EVENT to mitmproxy
[task 2024-02-10T09:47:20.174Z] 09:47:20     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process with exit code 3221225786
[task 2024-02-10T09:47:20.175Z] 09:47:20     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2024-02-10T09:47:20.175Z] 09:47:20     INFO -  raptor-mitmproxy Info: writing: C:\Users\task_1707526604\build\application\firefox\distribution\policies.json
[task 2024-02-10T09:47:20.176Z] 09:47:20     INFO -  raptor-perftest Info: Removing temporary directory: C:\Users\task_1707526604\AppData\Local\Temp\tmpgn1o97tm
[task 2024-02-10T09:47:20.202Z] 09:47:20    ERROR -  Traceback (most recent call last):
[task 2024-02-10T09:47:20.202Z] 09:47:20     INFO -    File "C:\Users\task_1707526604\build\tests\raptor\raptor\raptor.py", line 187, in <module>
[task 2024-02-10T09:47:20.202Z] 09:47:20     INFO -      main()
[task 2024-02-10T09:47:20.203Z] 09:47:20     INFO -    File "C:\Users\task_1707526604\build\tests\raptor\raptor\raptor.py", line 136, in main
[task 2024-02-10T09:47:20.203Z] 09:47:20     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2024-02-10T09:47:20.204Z] 09:47:20     INFO -    File "C:\Users\task_1707526604\build\tests\raptor\raptor\perftest.py", line 492, in run_tests
[task 2024-02-10T09:47:20.204Z] 09:47:20     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2024-02-10T09:47:20.205Z] 09:47:20     INFO -    File "C:\Users\task_1707526604\build\tests\raptor\raptor\browsertime\base.py", line 1029, in run_test
[task 2024-02-10T09:47:20.205Z] 09:47:20     INFO -      raise Exception(self.browsertime_failure)
[task 2024-02-10T09:47:20.205Z] 09:47:20     INFO -  Exception: ScriptTimeoutError: Timed out after 1800000 ms
[task 2024-02-10T09:47:20.239Z] 09:47:20     INFO - Return code: 1
[task 2024-02-10T09:47:20.240Z] 09:47:20  WARNING - setting return code to 1
[task 2024-02-10T09:47:20.240Z] 09:47:20     INFO - Copying Raptor results to upload dir:
[task 2024-02-10T09:47:20.240Z] 09:47:20     INFO - C:\Users\task_1707526604\build\blobber_upload_dir\perfherder-data.json
[task 2024-02-10T09:47:20.240Z] 09:47:20     INFO - Copying raptor results from C:\Users\task_1707526604\build\raptor.json to C:\Users\task_1707526604\build\blobber_upload_dir\perfherder-data.json
[task 2024-02-10T09:47:20.240Z] 09:47:20 CRITICAL - Error copying results C:\Users\task_1707526604\build\raptor.json to upload dir C:\Users\task_1707526604\build\blobber_upload_dir\perfherder-data.json
[task 2024-02-10T09:47:20.240Z] 09:47:20     INFO - [Errno 2] No such file or directory: 'C:\\Users\\task_1707526604\\build\\raptor.json'
[task 2024-02-10T09:47:20.241Z] 09:47:20     INFO - Running post-action listener: _package_coverage_data
[task 2024-02-10T09:47:20.241Z] 09:47:20     INFO - Running post-action listener: _resource_record_post_action
[task 2024-02-10T09:47:20.241Z] 09:47:20     INFO - Running post-action listener: process_java_coverage_data
[task 2024-02-10T09:47:20.241Z] 09:47:20     INFO - Running post-action listener: stop_device
[task 2024-02-10T09:47:20.242Z] 09:47:20     INFO - [mozharness: 2024-02-10 09:47:20.241872Z] Finished run-tests step (success)
[task 2024-02-10T09:47:20.242Z] 09:47:20     INFO - Running post-run listener: _resource_record_post_run
[task 2024-02-10T09:47:21.234Z] 09:47:21     INFO - Total resource usage - Wall time: 1876s; CPU: 0%; Read bytes: 120877056; Write bytes: 567124480; Read time: 1; Write time: 198
[task 2024-02-10T09:47:21.234Z] 09:47:21     INFO - TinderboxPrint: CPU usage<br/>0.4%
[task 2024-02-10T09:47:21.234Z] 09:47:21     INFO - TinderboxPrint: I/O read bytes / time<br/>120,877,056 / 1
[task 2024-02-10T09:47:21.234Z] 09:47:21     INFO - TinderboxPrint: I/O write bytes / time<br/>567,124,480 / 198
[task 2024-02-10T09:47:21.234Z] 09:47:21     INFO - TinderboxPrint: CPU idle<br/>14,935.5 (99.6%)
[task 2024-02-10T09:47:21.238Z] 09:47:21     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-02-10T09:47:21.242Z] 09:47:21     INFO - install - Wall time: 3s; CPU: 17%; Read bytes: 79360; Write bytes: 11911168; Read time: 0; Write time: 0
[task 2024-02-10T09:47:21.374Z] 09:47:21     INFO - run-tests - Wall time: 1873s; CPU: 0%; Read bytes: 120797696; Write bytes: 555213312; Read time: 1; Write time: 198
[task 2024-02-10T09:47:26.924Z] 09:47:26  WARNING - returning nonzero exit status 1
[taskcluster 2024-02-10T09:47:27.086Z]    Exit Code: 1
[taskcluster 2024-02-10T09:47:27.086Z]    User Time: 0s
[taskcluster 2024-02-10T09:47:27.086Z]  Kernel Time: 15.625ms
[taskcluster 2024-02-10T09:47:27.086Z]    Wall Time: 33m35.4739154s
[taskcluster 2024-02-10T09:47:27.086Z]       Result: FAILED
[taskcluster 2024-02-10T09:47:27.086Z] === Task Finished ===
[taskcluster 2024-02-10T09:47:27.086Z] Task Duration: 33m35.4739154s
[taskcluster 2024-02-10T09:47:27.162Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2025-02-09T07:10:13.838Z
[taskcluster 2024-02-10T09:47:27.490Z] Uploading artifact public/test_info/mitmproxy.log from file build\blobber_upload_dir\mitmproxy.log with content encoding "gzip", mime type "text/plain" and expiry 2025-02-09T07:10:13.838Z
[taskcluster 2024-02-10T09:47:27.750Z] Uploading artifact public/test_info/profile_resource-usage.json from file build\blobber_upload_dir\profile_resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2025-02-09T07:10:13.838Z
[taskcluster 2024-02-10T09:47:28.138Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2025-02-09T07:10:13.838Z
[taskcluster 2024-02-10T09:47:28.714Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BiSW4KWBThWE_o5e-M_xtQ/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2025-02-09T07:10:13.838Z
[taskcluster:error] exit status 1

Comment 1

[Intermittent Failures Robot]

1 failures in 4009 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1879702&startday=2024-02-05&endday=2024-02-11&tree=all

Comment 2

[Intermittent Failures Robot]

3 failures in 3382 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• windows10-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1879702&startday=2024-02-19&endday=2024-02-25&tree=all

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Comment 4

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=454160762&repo=mozilla-central

Comment 5

[Intermittent Failures Robot]

1 failures in 3235 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1879702&startday=2024-04-08&endday=2024-04-14&tree=all