1850659 - Perma [tier 2] speedometer subprocess.CalledProcessError: Command '['git', 'checkout', '36712deb57d45879f56dd2136f8a6ed8a22d964b']' returned non-zero exit status 1.

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-08-30T03:34:41.185Z] 03:34:41     INFO -  condprof INFO | Creating metadata...
[task 2023-08-30T03:34:41.188Z] 03:34:41     INFO -  condprof INFO | Saving metadata file in /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpwhb42t5b/profile/condprofile.json
[task 2023-08-30T03:34:41.188Z] 03:34:41     INFO -  condprof INFO | Profile at /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpwhb42t5b/profile.
[task 2023-08-30T03:34:41.188Z] 03:34:41     INFO -  Done.
[task 2023-08-30T03:34:41.423Z] 03:34:41     INFO -  raptor-perftest Info: Created a conditioned-profile copy: /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmp__newml3/profile
[task 2023-08-30T03:34:41.424Z] 03:34:41     INFO -  raptor-perftest Info: Merging profile: /opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/profile_data/base
[task 2023-08-30T03:34:41.429Z] 03:34:41     INFO -  raptor-perftest Info: Merging profile: /opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/profile_data/common
[task 2023-08-30T03:34:41.432Z] 03:34:41     INFO -  raptor-perftest Info: Merging profile: /opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/profile_data/perf
[task 2023-08-30T03:34:41.438Z] 03:34:41     INFO -  raptor-perftest Info: Merging profile: /opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/profile_data/raptor
[task 2023-08-30T03:34:41.439Z] 03:34:41     INFO -  raptor-perftest Info: Browser preferences: {'fission.autostart': True}
[task 2023-08-30T03:34:41.440Z] 03:34:41     INFO -  raptor-perftest Info: Local browser profile: /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmp__newml3/profile
[task 2023-08-30T03:34:41.440Z] 03:34:41     INFO -  raptor-browsertime Info: Removing mozprofile delimiters from browser profile
[task 2023-08-30T03:34:41.440Z] 03:34:41     INFO -  raptor-browsertime Info: cwd: '/opt/worker/tasks/task_169336354237148/build'
[task 2023-08-30T03:34:41.441Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_node: /opt/worker/tasks/task_169336354237148/fetches/node/bin/node
[task 2023-08-30T03:34:41.441Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_node: os.stat_result(st_mode=33261, st_ino=511014819, st_dev=16777222, st_nlink=1, st_uid=36, st_gid=20, st_size=82563760, st_atime=1693366361, st_mtime=1670920349, st_ctime=1693366362)
[task 2023-08-30T03:34:41.441Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_browsertimejs: /opt/worker/tasks/task_169336354237148/fetches/browsertime/node_modules/browsertime/bin/browsertime.js
[task 2023-08-30T03:34:41.441Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_browsertimejs: os.stat_result(st_mode=33261, st_ino=511014764, st_dev=16777222, st_nlink=1, st_uid=36, st_gid=20, st_size=7076, st_atime=1693366361, st_mtime=1692077213, st_ctime=1693366361)
[task 2023-08-30T03:34:41.442Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_geckodriver: /opt/worker/tasks/task_169336354237148/fetches/geckodriver
[task 2023-08-30T03:34:41.442Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_geckodriver: os.stat_result(st_mode=33261, st_ino=511013281, st_dev=16777222, st_nlink=1, st_uid=36, st_gid=20, st_size=5451856, st_atime=1693366360, st_mtime=1693257306, st_ctime=1693366360)
[task 2023-08-30T03:34:41.442Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_chromedriver: /opt/worker/tasks/task_169336354237148/fetches/{}chromedriver
[task 2023-08-30T03:34:41.442Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_chromedriver: [Errno 2] No such file or directory: '/opt/worker/tasks/task_169336354237148/fetches/{}chromedriver'
[task 2023-08-30T03:34:41.442Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_user_args: []
[task 2023-08-30T03:34:41.443Z] 03:34:41     INFO -  raptor-browsertime Info: browsertime_user_args: stat: path should be string, bytes, os.PathLike or integer, not list
[task 2023-08-30T03:34:41.443Z] 03:34:41     INFO -  raptor-perftest Info: starting test: speedometer3
[task 2023-08-30T03:34:41.453Z] 03:34:41     INFO -  raptor-benchmark Info: Cloning the benchmarks to /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpd7tu7vh_/performance-tests/Speedometer
[task 2023-08-30T03:34:41.457Z] 03:34:41     INFO -  Cloning into '/private/var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmpd7tu7vh_/performance-tests/Speedometer'...
[task 2023-08-30T03:34:43.564Z] 03:34:43     INFO -  warning: the following paths have collided (e.g. case-sensitive paths
[task 2023-08-30T03:34:43.564Z] 03:34:43     INFO -  on a case-insensitive filesystem) and only one from the same
[task 2023-08-30T03:34:43.564Z] 03:34:43     INFO -  colliding group is in the working tree:
[task 2023-08-30T03:34:43.564Z] 03:34:43     INFO -    'resources/todomvc/architecture-examples/react-complex/README.md'
[task 2023-08-30T03:34:43.564Z] 03:34:43     INFO -    'resources/todomvc/architecture-examples/react-complex/readme.md'
[task 2023-08-30T03:34:43.572Z] 03:34:43     INFO -  36712deb57d45879f56dd2136f8a6ed8a22d964b
[task 2023-08-30T03:34:43.572Z] 03:34:43     INFO -  raptor-benchmark Info: Given benchmark repository revision verified
[task 2023-08-30T03:34:43.657Z] 03:34:43     INFO -  error: Your local changes to the following files would be overwritten by checkout:
[task 2023-08-30T03:34:43.657Z] 03:34:43     INFO -  	resources/todomvc/architecture-examples/react-complex/README.md
[task 2023-08-30T03:34:43.657Z] 03:34:43     INFO -  Please commit your changes or stash them before you switch branches.
[task 2023-08-30T03:34:43.658Z] 03:34:43     INFO -  Aborting
[task 2023-08-30T03:34:43.658Z] 03:34:43     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/xb/d469slf94hl9z0dsgjcwr3t8000014/T/tmp__newml3
[task 2023-08-30T03:34:43.709Z] 03:34:43    ERROR -  Traceback (most recent call last):
[task 2023-08-30T03:34:43.709Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/raptor.py", line 190, in <module>
[task 2023-08-30T03:34:43.709Z] 03:34:43     INFO -      main()
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/raptor.py", line 136, in main
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/perftest.py", line 469, in run_tests
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/browsertime/base.py", line 842, in run_test
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -      self.run_test_setup(test)
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/browsertime/base.py", line 122, in run_test_setup
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -      self.benchmark = Benchmark(self.config, test, debug_mode=self.debug_mode)
[task 2023-08-30T03:34:43.710Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/benchmark.py", line 45, in __init__
[task 2023-08-30T03:34:43.711Z] 03:34:43     INFO -      run_local=self.config.get("run_local", False),
[task 2023-08-30T03:34:43.711Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/benchmark.py", line 351, in setup_benchmarks
[task 2023-08-30T03:34:43.711Z] 03:34:43     INFO -      mozbuild_path, bench_dir, run_local=run_local
[task 2023-08-30T03:34:43.711Z] 03:34:43     INFO -    File "/opt/worker/tasks/task_169336354237148/build/tests/raptor/raptor/benchmark.py", line 294, in _setup_git_benchmarks
[task 2023-08-30T03:34:43.711Z] 03:34:43     INFO -      ["git", "checkout", benchmark_revision], cwd=external_repo_path
[task 2023-08-30T03:34:43.711Z] 03:34:43     INFO -    File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/subprocess.py", line 363, in check_call
[task 2023-08-30T03:34:43.712Z] 03:34:43     INFO -      raise CalledProcessError(retcode, cmd)
[task 2023-08-30T03:34:43.712Z] 03:34:43     INFO -  subprocess.CalledProcessError: Command '['git', 'checkout', '36712deb57d45879f56dd2136f8a6ed8a22d964b']' returned non-zero exit status 1.
[task 2023-08-30T03:34:43.742Z] 03:34:43     INFO - Return code: 1
[task 2023-08-30T03:34:43.742Z] 03:34:43  WARNING - setting return code to 1
[task 2023-08-30T03:34:43.742Z] 03:34:43     INFO - Copying Raptor results to upload dir:
[task 2023-08-30T03:34:43.742Z] 03:34:43     INFO - /opt/worker/tasks/task_169336354237148/build/blobber_upload_dir/perfherder-data.json
[task 2023-08-30T03:34:43.742Z] 03:34:43     INFO - Copying raptor results from /opt/worker/tasks/task_169336354237148/build/raptor.json to /opt/worker/tasks/task_169336354237148/build/blobber_upload_dir/perfherder-data.json
[task 2023-08-30T03:34:43.743Z] 03:34:43 CRITICAL - Error copying results /opt/worker/tasks/task_169336354237148/build/raptor.json to upload dir /opt/worker/tasks/task_169336354237148/build/blobber_upload_dir/perfherder-data.json
[task 2023-08-30T03:34:43.743Z] 03:34:43     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_169336354237148/build/raptor.json'
[task 2023-08-30T03:34:43.743Z] 03:34:43     INFO - Running post-action listener: _package_coverage_data
[task 2023-08-30T03:34:43.743Z] 03:34:43     INFO - Running post-action listener: _resource_record_post_action
[task 2023-08-30T03:34:43.743Z] 03:34:43     INFO - Running post-action listener: process_java_coverage_data
[task 2023-08-30T03:34:43.743Z] 03:34:43     INFO - Running post-action listener: stop_device
[task 2023-08-30T03:34:43.743Z] 03:34:43     INFO - [mozharness: 2023-08-30 03:34:43.743886Z] Finished run-tests step (success)
[task 2023-08-30T03:34:43.743Z] 03:34:43     INFO - Running post-run listener: _resource_record_post_run
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - Total resource usage - Wall time: 56s; CPU: 8%; Read bytes: 55128064; Write bytes: 405778432; Read time: 650; Write time: 915
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - TinderboxPrint: CPU usage<br/>7.8%
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - TinderboxPrint: I/O read bytes / time<br/>55,128,064 / 650
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - TinderboxPrint: I/O write bytes / time<br/>405,778,432 / 915
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - TinderboxPrint: CPU idle<br/>619.2 (92.2%)
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - TinderboxPrint: CPU system<br/>11.0 (1.6%)
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - TinderboxPrint: CPU user<br/>41.6 (6.2%)
[task 2023-08-30T03:34:43.807Z] 03:34:43     INFO - TinderboxPrint: Swap in / out<br/>312,266,752 / 0
[task 2023-08-30T03:34:43.807Z] 03:34:43     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 2023-08-30T03:34:43.808Z] 03:34:43     INFO - install - Wall time: 20s; CPU: 14%; Read bytes: 252663296; Write bytes: 247324672; Read time: 16929; Write time: 370
[task 2023-08-30T03:34:43.808Z] 03:34:43     INFO - run-tests - Wall time: 37s; CPU: 4%; Read bytes: 52543488; Write bytes: 142594048; Read time: 608; Write time: 515
[task 2023-08-30T03:34:43.821Z] 03:34:43  WARNING - returning nonzero exit status 1
[taskcluster 2023-08-30T03:34:43.845Z]    Exit Code: 1
[taskcluster 2023-08-30T03:34:43.845Z]    User Time: 1m9.101982s
[taskcluster 2023-08-30T03:34:43.845Z]  Kernel Time: 15.1537s
[taskcluster 2023-08-30T03:34:43.845Z]    Wall Time: 2m3.873372s
[taskcluster 2023-08-30T03:34:43.845Z]       Result: FAILED
[taskcluster 2023-08-30T03:34:43.845Z] === Task Finished ===
[taskcluster 2023-08-30T03:34:43.845Z] Task Duration: 2m3.876993s
[taskcluster 2023-08-30T03:34:43.954Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-08-29T01:53:34.311Z
[taskcluster 2023-08-30T03:34:44.899Z] 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 2024-08-29T01:53:34.311Z
[taskcluster 2023-08-30T03:34:45.430Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/F2Pid8OBSzy2Xc-u5ZuUKQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2024-08-29T01:53:34.311Z
[taskcluster:error] exit status 1

Comment 1

[Iulian Moraru]

Hi Greg! Can you please take a look at this? It seems to be caused by something off tree, jobs are now failing even where they were green.
Thank you!

Comment 2

[Cosmin Sabou [:CosminS]]

That revision number leads to this - https://github.com/WebKit/Speedometer/pull/283

Comment 3

[Greg Mierzwinski [:sparky]]

This was caused by an upstream update that broke git clone for case-insensitive systems. The following PR should resolve the issue: https://github.com/WebKit/Speedometer/pull/303

Comment 4

[Greg Mierzwinski [:sparky]]

This should be fixed in the next mozilla-central push. Thank you for the ping, and let me know if there are still issues.

Comment 5

[Intermittent Failures Robot]

19 failures in 563 pushes (0.034 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 8
• mozilla-central: 11

Platform and build breakdown:

• macosx1015-64-nightlyasrelease-qr: 2
  • opt: 2
• macosx1015-64-shippable-qr: 6
  • opt: 6
• macosx1300-64-shippable-qr: 5
  • opt: 5
• windows10-64-shippable-qr: 5
  • opt: 5
• windows10-64-nightlyasrelease-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1850659&startday=2023-08-30&endday=2023-08-30&tree=all

Comment 6

[Greg Mierzwinski [:sparky]]

Fixed now: https://treeherder.mozilla.org/jobs?repo=mozilla-central&tier=1%2C2%2C3&searchStr=speedometer&revision=01e6745f9ba2e0920482c15dcf09aa1c27a18f7b

Comment 7

[Intermittent Failures Robot]

20 failures in 3019 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 9
• mozilla-central: 11

Platform and build breakdown:

• macosx1015-64-nightlyasrelease-qr: 3
  • opt: 3
• macosx1015-64-shippable-qr: 6
  • opt: 6
• macosx1300-64-shippable-qr: 5
  • opt: 5
• windows10-64-shippable-qr: 5
  • opt: 5
• windows10-64-nightlyasrelease-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1850659&startday=2023-08-28&endday=2023-09-03&tree=all