1790208 - Intermittent [Tier 2] raptor-browsertime Critical: Browsertime process timed out after waiting 120 seconds for output

Status: RESOLVED DUPLICATE of bug 1774954

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

task 2022-09-10T12:05:18.769Z] 12:05:18     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2022-09-10T12:05:23.931Z] 12:05:23     INFO -  raptor-browsertime Info: Navigating to primary url:https://imgur.com/gallery/m5tYJL6
[task 2022-09-10T12:05:23.931Z] 12:05:23     INFO -  raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2022-09-10T12:05:25.068Z] 12:05:25     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2022-09-10T12:05:25.068Z] 12:05:25     INFO -  raptor-browsertime Info: Testing url https://imgur.com/gallery/m5tYJL6 iteration 1
[task 2022-09-10T12:05:25.069Z] 12:05:25     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-09-10T12:05:34.652Z] 12:05:34     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2022-09-10T12:07:34.917Z] 12:07:34 CRITICAL -  raptor-browsertime Critical: Browsertime process timed out after waiting 120 seconds for output
[task 2022-09-10T12:07:34.917Z] 12:07:34     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2022-09-10T12:07:34.918Z] 12:07:34     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2022-09-10T12:07:34.918Z] 12:07:34     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 1347
[task 2022-09-10T12:07:36.088Z] 12:07:36    ERROR -  raptor-mitmproxy Error: Mitmproxy exited with error code -9
[task 2022-09-10T12:07:36.088Z] 12:07:36     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2022-09-10T12:07:36.089Z] 12:07:36     INFO -  raptor-mitmproxy Info: writing: /opt/worker/tasks/task_166281064703805/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
[task 2022-09-10T12:07:36.089Z] 12:07:36     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/vv/w76hxdts3mz037wkr6bwnpgr000014/T/tmpbwoq0u2p
[task 2022-09-10T12:08:01.374Z] 12:08:01    ERROR -  Traceback (most recent call last):
[task 2022-09-10T12:08:01.374Z] 12:08:01     INFO -    File "/opt/worker/tasks/task_166281064703805/build/tests/raptor/raptor/raptor.py", line 206, in <module>
[task 2022-09-10T12:08:01.374Z] 12:08:01     INFO -      main()
[task 2022-09-10T12:08:01.375Z] 12:08:01     INFO -    File "/opt/worker/tasks/task_166281064703805/build/tests/raptor/raptor/raptor.py", line 152, in main
[task 2022-09-10T12:08:01.375Z] 12:08:01     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-09-10T12:08:01.375Z] 12:08:01     INFO -    File "/opt/worker/tasks/task_166281064703805/build/tests/raptor/raptor/perftest.py", line 467, in run_tests
[task 2022-09-10T12:08:01.375Z] 12:08:01     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-09-10T12:08:01.376Z] 12:08:01     INFO -    File "/opt/worker/tasks/task_166281064703805/build/tests/raptor/raptor/browsertime/base.py", line 792, in run_test
[task 2022-09-10T12:08:01.376Z] 12:08:01     INFO -      f"Browsertime process timed out after waiting {output_timeout} seconds "
[task 2022-09-10T12:08:01.376Z] 12:08:01     INFO -  Exception: Browsertime process timed out after waiting 120 seconds for output
[task 2022-09-10T12:08:01.523Z] 12:08:01    ERROR - Return code: 1
[task 2022-09-10T12:08:01.523Z] 12:08:01  WARNING - setting return code to 1
[task 2022-09-10T12:08:01.523Z] 12:08:01     INFO - Copying Raptor results to upload dir:
[task 2022-09-10T12:08:01.523Z] 12:08:01     INFO - /opt/worker/tasks/task_166281064703805/build/blobber_upload_dir/perfherder-data.json
[task 2022-09-10T12:08:01.523Z] 12:08:01     INFO - Copying raptor results from /opt/worker/tasks/task_166281064703805/build/raptor.json to /opt/worker/tasks/task_166281064703805/build/blobber_upload_dir/perfherder-data.json
[task 2022-09-10T12:08:01.523Z] 12:08:01 CRITICAL - Error copying results /opt/worker/tasks/task_166281064703805/build/raptor.json to upload dir /opt/worker/tasks/task_166281064703805/build/blobber_upload_dir/perfherder-data.json
[task 2022-09-10T12:08:01.523Z] 12:08:01     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_166281064703805/build/raptor.json'
[task 2022-09-10T12:08:01.524Z] 12:08:01     INFO - Running post-action listener: _package_coverage_data
[task 2022-09-10T12:08:01.524Z] 12:08:01     INFO - Running post-action listener: _resource_record_post_action
[task 2022-09-10T12:08:01.524Z] 12:08:01     INFO - Running post-action listener: process_java_coverage_data
[task 2022-09-10T12:08:01.524Z] 12:08:01     INFO - Running post-action listener: stop_device
[task 2022-09-10T12:08:01.524Z] 12:08:01     INFO - [mozharness: 2022-09-10 12:08:01.524222Z] Finished run-tests step (success)
[task 2022-09-10T12:08:01.524Z] 12:08:01     INFO - Running post-run listener: _resource_record_post_run
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - Total resource usage - Wall time: 413s; CPU: 6%; Read bytes: 8487256064; Write bytes: 1316990976; Read time: 653867; Write time: 439779
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - TinderboxPrint: CPU usage<br/>6.1%
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - TinderboxPrint: I/O read bytes / time<br/>8,487,256,064 / 653,867
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - TinderboxPrint: I/O write bytes / time<br/>1,316,990,976 / 439,779
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - TinderboxPrint: CPU idle<br/>4,462.0 (89.9%)
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - TinderboxPrint: CPU system<br/>96.1 (1.9%)
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - TinderboxPrint: CPU user<br/>403.6 (8.1%)
[task 2022-09-10T12:08:02.266Z] 12:08:02     INFO - TinderboxPrint: Swap in / out<br/>4,929,052,672 / 16,384
[task 2022-09-10T12:08:02.267Z] 12:08:02     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-09-10T12:08:02.268Z] 12:08:02     INFO - install - Wall time: 114s; CPU: 9%; Read bytes: 2753406464; Write bytes: 471539712; Read time: 212170; Write time: 143965
[task 2022-09-10T12:08:02.271Z] 12:08:02     INFO - run-tests - Wall time: 299s; CPU: 5%; Read bytes: 6095065088; Write bytes: 842801152; Read time: 457725; Write time: 294457
[task 2022-09-10T12:08:02.735Z] 12:08:02  WARNING - returning nonzero exit status 1
[taskcluster 2022-09-10T12:08:02.760Z]    Exit Code: 1
[taskcluster 2022-09-10T12:08:02.760Z]    User Time: 1m5.162101s
[taskcluster 2022-09-10T12:08:02.760Z]  Kernel Time: 14.762173s
[taskcluster 2022-09-10T12:08:02.760Z]    Wall Time: 10m59.614525s
[taskcluster 2022-09-10T12:08:02.760Z]       Result: FAILED
[taskcluster 2022-09-10T12:08:02.760Z] === Task Finished ===
[taskcluster 2022-09-10T12:08:02.760Z] Task Duration: 10m59.629643s
[taskcluster 2022-09-10T12:08:03.032Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:03.557Z] Uploading artifact public/test_info/browsertime-results/imgur/windowrecording-1662811525077.08/frame0383.png from file build/blobber_upload_dir/browsertime-results/imgur/windowrecording-1662811525077.08/frame0383.png with content encoding "identity", mime type "image/png" and expiry 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:04.112Z] Uploading artifact public/test_info/browsertime-results/imgur/windowrecording-1662811525077.08/frame0384.png from file build/blobber_upload_dir/browsertime-results/imgur/windowrecording-1662811525077.08/frame0384.png with content encoding "identity", mime type "image/png" and expiry 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:04.512Z] Uploading artifact public/test_info/browsertime-results/imgur/windowrecording-1662811525077.08/frame0385.png from file build/blobber_upload_dir/browsertime-results/imgur/windowrecording-1662811525077.08/frame0385.png with content encoding "identity", mime type "image/png" and expiry 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:04.889Z] Uploading artifact public/test_info/browsertime-results/imgur/windowrecording-1662811525077.08/frame0386.png from file build/blobber_upload_dir/browsertime-results/imgur/windowrecording-1662811525077.08/frame0386.png with content encoding "identity", mime type "image/png" and expiry 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:05.285Z] Uploading artifact public/test_info/browsertime-results/imgur/windowrecording-1662811525077.08/frame0387.png from file build/blobber_upload_dir/browsertime-results/imgur/windowrecording-1662811525077.08/frame0387.png with content encoding "identity", mime type "image/png" and expiry 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:05.620Z] 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 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:05.761Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2022-12-09T09:45:48.749Z
[taskcluster 2022-09-10T12:08:05.926Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/U4CH0xpoTY2XILYap7MI0Q/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-12-09T09:45:48.749Z
[taskcluster:error] exit status 1