1749351 - Intermittent raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 60000 ms

Status: RESOLVED DUPLICATE of bug 1768867

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-01-10T15:55:16.716Z] 15:55:16     INFO -  raptor-browsertime Info: Start to measure landing
[task 2022-01-10T15:55:16.717Z] 15:55:16     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-01-10T15:55:17.556Z] 15:55:17     INFO -  raptor-browsertime Info: Navigating to url https://www.cnn.com iteration 2
[task 2022-01-10T15:56:20.670Z] 15:56:20     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2022-01-10T15:57:20.760Z] 15:57:20    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2022-01-10T15:57:20.761Z] 15:57:20     INFO -  raptor-browsertime Info: Exception found while running `commands.measure.stop()`:
[task 2022-01-10T15:57:20.761Z] 15:57:20     INFO -  raptor-browsertime Info: ScriptTimeoutError: Timed out after 60000 ms
[task 2022-01-10T15:57:20.762Z] 15:57:20     INFO -  raptor-browsertime Info:     at Object.throwDecodedError (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/selenium-webdriver/lib/error.js:539:15)
[task 2022-01-10T15:57:20.762Z] 15:57:20     INFO -  raptor-browsertime Info:     at parseHttpResponse (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/selenium-webdriver/lib/http.js:647:13)
[task 2022-01-10T15:57:20.763Z] 15:57:20     INFO -  raptor-browsertime Info:     at Executor.execute (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/selenium-webdriver/lib/http.js:573:28)
[task 2022-01-10T15:57:20.763Z] 15:57:20     INFO -  raptor-browsertime Info:     at processTicksAndRejections (internal/process/task_queues.js:97:5)
[task 2022-01-10T15:57:20.763Z] 15:57:20     INFO -  raptor-browsertime Info:     at async Driver.execute (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/selenium-webdriver/lib/webdriver.js:735:17)
[task 2022-01-10T15:57:20.764Z] 15:57:20     INFO -  raptor-browsertime Info:     at async SeleniumRunner.runPrivilegedAsyncScript (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/lib/core/seleniumRunner.js:466:22)
[task 2022-01-10T15:57:20.764Z] 15:57:20     INFO -  raptor-browsertime Info:     at async FirefoxWindowRecorder.stop (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/lib/video/screenRecording/firefox/firefoxWindowRecorder.js:175:5)
[task 2022-01-10T15:57:20.764Z] 15:57:20     INFO -  raptor-browsertime Info:     at async Measure._stopVideo (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/lib/core/engine/command/measure.js:101:7)
[task 2022-01-10T15:57:20.765Z] 15:57:20     INFO -  raptor-browsertime Info:     at async Measure.stop (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/lib/core/engine/command/measure.js:287:5)
[task 2022-01-10T15:57:20.765Z] 15:57:20     INFO -  raptor-browsertime Info:     at async module.exports (/opt/worker/tasks/task_164182978786741/build/tests/raptor/browsertime/browsertime_interactive.js:88:9)
[task 2022-01-10T15:57:20.765Z] 15:57:20     INFO -  raptor-browsertime Info:     at async /opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/lib/core/engine/run.js:7:9
[task 2022-01-10T15:57:20.766Z] 15:57:20     INFO -  raptor-browsertime Info:     at async Iteration.run (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/lib/core/engine/iteration.js:214:9)
[task 2022-01-10T15:57:20.766Z] 15:57:20     INFO -  raptor-browsertime Info:     at async Engine.runByScript (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/lib/core/engine/index.js:277:20)
[task 2022-01-10T15:57:20.766Z] 15:57:20     INFO -  raptor-browsertime Info:     at async run (/opt/worker/tasks/task_164182978786741/fetches/browsertime/node_modules/browsertime/bin/browsertime.js:71:22)
[task 2022-01-10T15:57:20.766Z] 15:57:20 CRITICAL -  raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 60000 ms
[task 2022-01-10T15:57:20.766Z] 15:57:20     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2022-01-10T15:57:20.767Z] 15:57:20     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2022-01-10T15:57:20.767Z] 15:57:20     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 1030
[task 2022-01-10T15:57:21.390Z] 15:57:21     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2022-01-10T15:57:21.390Z] 15:57:21     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2022-01-10T15:57:21.390Z] 15:57:21     INFO -  raptor-mitmproxy Info: writing: /opt/worker/tasks/task_164182978786741/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
[task 2022-01-10T15:57:21.391Z] 15:57:21     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/_n/_w0qc4sj7cq6qdljzv2_cdpm000014/T/tmp0q3_q3vo
[task 2022-01-10T15:57:21.402Z] 15:57:21    ERROR -  Traceback (most recent call last):
[task 2022-01-10T15:57:21.403Z] 15:57:21     INFO -    File "/opt/worker/tasks/task_164182978786741/build/tests/raptor/raptor/raptor.py", line 215, in <module>
[task 2022-01-10T15:57:21.403Z] 15:57:21     INFO -      main()
[task 2022-01-10T15:57:21.403Z] 15:57:21     INFO -    File "/opt/worker/tasks/task_164182978786741/build/tests/raptor/raptor/raptor.py", line 161, in main
[task 2022-01-10T15:57:21.403Z] 15:57:21     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-01-10T15:57:21.403Z] 15:57:21     INFO -    File "/opt/worker/tasks/task_164182978786741/build/tests/raptor/raptor/perftest.py", line 450, in run_tests
[task 2022-01-10T15:57:21.404Z] 15:57:21     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-01-10T15:57:21.404Z] 15:57:21     INFO -    File "/opt/worker/tasks/task_164182978786741/build/tests/raptor/raptor/browsertime/base.py", line 555, in run_test
[task 2022-01-10T15:57:21.404Z] 15:57:21     INFO -      raise Exception(self.browsertime_failure)
[task 2022-01-10T15:57:21.404Z] 15:57:21     INFO -  Exception: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 60000 ms
[task 2022-01-10T15:57:21.495Z] 15:57:21    ERROR - Return code: 1
[task 2022-01-10T15:57:21.495Z] 15:57:21  WARNING - setting return code to 1
[task 2022-01-10T15:57:21.495Z] 15:57:21     INFO - Copying Raptor results to upload dir:
[task 2022-01-10T15:57:21.495Z] 15:57:21     INFO - /opt/worker/tasks/task_164182978786741/build/blobber_upload_dir/perfherder-data.json
[task 2022-01-10T15:57:21.495Z] 15:57:21     INFO - Copying raptor results from /opt/worker/tasks/task_164182978786741/build/raptor.json to /opt/worker/tasks/task_164182978786741/build/blobber_upload_dir/perfherder-data.json
[task 2022-01-10T15:57:21.495Z] 15:57:21 CRITICAL - Error copying results /opt/worker/tasks/task_164182978786741/build/raptor.json to upload dir /opt/worker/tasks/task_164182978786741/build/blobber_upload_dir/perfherder-data.json
[task 2022-01-10T15:57:21.495Z] 15:57:21     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_164182978786741/build/raptor.json'
[task 2022-01-10T15:57:21.496Z] 15:57:21     INFO - Running post-action listener: _package_coverage_data
[task 2022-01-10T15:57:21.496Z] 15:57:21     INFO - Running post-action listener: _resource_record_post_action
[task 2022-01-10T15:57:21.496Z] 15:57:21     INFO - Running post-action listener: process_java_coverage_data
[task 2022-01-10T15:57:21.496Z] 15:57:21     INFO - Running post-action listener: stop_device
[task 2022-01-10T15:57:21.496Z] 15:57:21     INFO - [mozharness: 2022-01-10 15:57:21.496624Z] Finished run-tests step (success)
[task 2022-01-10T15:57:21.496Z] 15:57:21     INFO - Running post-run listener: _resource_record_post_run
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - Total resource usage - Wall time: 272s; CPU: 7%; Read bytes: 115605504; Write bytes: 1939447808; Read time: 1538; Write time: 2546
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - TinderboxPrint: CPU usage<br/>7.4%
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - TinderboxPrint: I/O read bytes / time<br/>115,605,504 / 1,538
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - TinderboxPrint: I/O write bytes / time<br/>1,939,447,808 / 2,546
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - TinderboxPrint: CPU idle<br/>2,962.6 (90.8%)
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - TinderboxPrint: CPU system<br/>69.5 (2.1%)
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - TinderboxPrint: CPU user<br/>229.3 (7.0%)
[task 2022-01-10T15:57:21.609Z] 15:57:21     INFO - TinderboxPrint: Swap in / out<br/>551,895,040 / 212,992
[task 2022-01-10T15:57:21.609Z] 15:57: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 2022-01-10T15:57:21.610Z] 15:57:21     INFO - install - Wall time: 32s; CPU: 14%; Read bytes: 433604096; Write bytes: 428486656; Read time: 28654; Write time: 581
[task 2022-01-10T15:57:21.612Z] 15:57:21     INFO - run-tests - Wall time: 240s; CPU: 7%; Read bytes: 106397696; Write bytes: 1498062848; Read time: 1321; Write time: 1948
[task 2022-01-10T15:57:21.675Z] 15:57:21  WARNING - returning nonzero exit status 1
[taskcluster 2022-01-10T15:57:21.705Z]    Exit Code: 1
[taskcluster 2022-01-10T15:57:21.705Z]    User Time: 2m20.491799s
[taskcluster 2022-01-10T15:57:21.705Z]  Kernel Time: 23.283208s
[taskcluster 2022-01-10T15:57:21.705Z]    Wall Time: 5m45.077119s
[taskcluster 2022-01-10T15:57:21.705Z]       Result: FAILED
[taskcluster 2022-01-10T15:57:21.705Z] === Task Finished ===
[taskcluster 2022-01-10T15:57:21.706Z] Task Duration: 5m45.081313s

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1749351&startday=2022-01-10&endday=2022-01-16&tree=all

Comment 2

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

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

Comment 3

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=367347159&repo=autoland

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1749351&startday=2022-02-07&endday=2022-02-13&tree=all

Comment 5

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

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

Comment 6

[Treeherder Bug Filer]

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

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1749351&startday=2022-03-28&endday=2022-04-03&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1749351&startday=2022-04-18&endday=2022-04-24&tree=all

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 5

Platform and build breakdown:

• macosx1015-64-shippable-qr: 5
  • opt: 5

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