Closed Bug 1884354 Opened 2 years ago Closed 9 months ago

Frequent subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation] returned non-zero exit status 128.

Categories

(Testing :: Raptor, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell infra])

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


[task 2024-03-08T11:15:22.739Z] 11:15:22     INFO -  raptor-main Info: matrix-react-bench
[task 2024-03-08T11:15:22.739Z] 11:15:22     INFO -  raptor-perftest Info: Using an empty profile.
[task 2024-03-08T11:15:22.740Z] 11:15:22     INFO -  raptor-perftest Warning: [chrome] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /opt/google/chrome
[task 2024-03-08T11:15:22.740Z] 11:15:22     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2024-03-08T11:15:22.802Z] 11:15:22     INFO -  raptor-perftest Info: Browser name: chrome
[task 2024-03-08T11:15:22.803Z] 11:15:22     INFO -  raptor-perftest Info: Browser version: 122.0.6261.111
[task 2024-03-08T11:15:22.803Z] 11:15:22     INFO -  raptor-perftest Warning: [chrome] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /opt/google/chrome
[task 2024-03-08T11:15:22.803Z] 11:15:22     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2024-03-08T11:15:22.828Z] 11:15:22     INFO -  raptor-perftest Info: Browser name: chrome
[task 2024-03-08T11:15:22.828Z] 11:15:22     INFO -  raptor-perftest Info: Browser version: 122.0.6261.111
[task 2024-03-08T11:15:22.829Z] 11:15:22     INFO -  raptor-perftest Info: Post startup delay set to 30000 ms
[task 2024-03-08T11:15:22.831Z] 11:15:22     INFO -  raptor-perftest Info: main raptor init, config is: {'app': 'chrome', 'binary': '/usr/bin/google-chrome', 'platform': 'linux', 'processor': 'x86_64', 'run_local': False, 'obj_path': None, 'gecko_profile': False, 'gecko_profile_interval': None, 'gecko_profile_entries': None, 'gecko_profile_extra_threads': [], 'gecko_profile_threads': None, 'gecko_profile_features': None, 'extra_profiler_run': True, 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FsYusge8QLKspdrl1moc-g/artifacts/public/build/target.crashreporter-symbols.zip', 'host': '127.0.0.1', 'cold': False, 'live_sites': False, 'is_release_build': False, 'e10s': True, 'device_name': None, 'fission': True, 'disable_perf_tuning': False, 'conditioned_profile': None, 'test_bytecode_cache': False, 'chimera': False, 'extra_prefs': {'fission.autostart': True}, 'environment': {}, 'project': 'mozilla-central', 'verbose': False, 'extra_summary_methods': [], 'benchmark_repository': None, 'benchmark_revision': None, 'benchmark_branch': None, 'clean': False, 'screenshot_on_failure': True}
[task 2024-03-08T11:15:22.831Z] 11:15:22     INFO -  raptor-browsertime Info: cwd: '/home/cltbld/tasks/task_170989642618752/build'
[task 2024-03-08T11:15:22.831Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_node: /home/cltbld/tasks/task_170989642618752/fetches/node/bin/node
[task 2024-03-08T11:15:22.832Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_node: os.stat_result(st_mode=33261, st_ino=9360671, st_dev=64768, st_nlink=1, st_uid=1006, st_gid=1007, st_size=92930512, st_atime=1709896430, st_mtime=1708940159, st_ctime=1709896430)
[task 2024-03-08T11:15:22.832Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_browsertimejs: /home/cltbld/tasks/task_170989642618752/fetches/browsertime/node_modules/browsertime/bin/browsertime.js
[task 2024-03-08T11:15:22.833Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_browsertimejs: os.stat_result(st_mode=33261, st_ino=9329330, st_dev=64768, st_nlink=1, st_uid=1006, st_gid=1007, st_size=7076, st_atime=1709896430, st_mtime=1708958795, st_ctime=1709896430)
[task 2024-03-08T11:15:22.833Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_geckodriver: /home/cltbld/tasks/task_170989642618752/fetches/geckodriver
[task 2024-03-08T11:15:22.834Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_geckodriver: os.stat_result(st_mode=33261, st_ino=9322545, st_dev=64768, st_nlink=1, st_uid=1006, st_gid=1007, st_size=9794056, st_atime=1709896430, st_mtime=1707775093, st_ctime=1709896430)
[task 2024-03-08T11:15:22.834Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_chromedriver: /home/cltbld/tasks/task_170989642618752/fetches/{}chromedriver
[task 2024-03-08T11:15:22.835Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_chromedriver: [Errno 2] No such file or directory: '/home/cltbld/tasks/task_170989642618752/fetches/{}chromedriver'
[task 2024-03-08T11:15:22.835Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_user_args: []
[task 2024-03-08T11:15:22.835Z] 11:15:22     INFO -  raptor-browsertime Info: browsertime_user_args: stat: path should be string, bytes, os.PathLike or integer, not list
[task 2024-03-08T11:15:22.836Z] 11:15:22     INFO -  raptor-perftest Info: starting test: matrix-react-bench
[task 2024-03-08T11:15:22.836Z] 11:15:22     INFO -  raptor-benchmark Info: Cloning the benchmarks to /tmp/tmpbmssby4g/performance-tests/perf-automation
[task 2024-03-08T11:15:22.836Z] 11:15:22     INFO -  Cloning into '/tmp/tmpbmssby4g/performance-tests/perf-automation'...
[task 2024-03-08T11:17:03.448Z] 11:17:03     INFO -  error: RPC failed; curl 56 GnuTLS recv error (-9): A TLS packet with unexpected length was received.
[task 2024-03-08T11:17:03.449Z] 11:17:03     INFO -  error: 1473 bytes of body are still expected
[task 2024-03-08T11:17:03.450Z] 11:17:03     INFO -  fetch-pack: unexpected disconnect while reading sideband packet
[task 2024-03-08T11:17:03.450Z] 11:17:03     INFO -  fatal: early EOF
[task 2024-03-08T11:17:03.450Z] 11:17:03     INFO -  fatal: fetch-pack: invalid index-pack output
[task 2024-03-08T11:17:03.454Z] 11:17:03    ERROR -  Traceback (most recent call last):
[task 2024-03-08T11:17:03.455Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/raptor.py", line 188, in <module>
[task 2024-03-08T11:17:03.455Z] 11:17:03     INFO -      main()
[task 2024-03-08T11:17:03.455Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/raptor.py", line 137, in main
[task 2024-03-08T11:17:03.455Z] 11:17:03     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2024-03-08T11:17:03.456Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/perftest.py", line 500, in run_tests
[task 2024-03-08T11:17:03.456Z] 11:17:03     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2024-03-08T11:17:03.456Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/browsertime/base.py", line 910, in run_test
[task 2024-03-08T11:17:03.456Z] 11:17:03     INFO -      self.run_test_setup(test)
[task 2024-03-08T11:17:03.457Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/browsertime/base.py", line 156, in run_test_setup
[task 2024-03-08T11:17:03.457Z] 11:17:03     INFO -      self.benchmark = Benchmark(self.config, test, debug_mode=self.debug_mode)
[task 2024-03-08T11:17:03.457Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/benchmark.py", line 42, in __init__
[task 2024-03-08T11:17:03.457Z] 11:17:03     INFO -      self.setup_benchmarks(
[task 2024-03-08T11:17:03.458Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/benchmark.py", line 350, in setup_benchmarks
[task 2024-03-08T11:17:03.458Z] 11:17:03     INFO -      bench_dir = self._setup_git_benchmarks(
[task 2024-03-08T11:17:03.458Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/benchmark.py", line 271, in _setup_git_benchmarks
[task 2024-03-08T11:17:03.459Z] 11:17:03     INFO -      self._full_clone(benchmark_repository, external_repo_path)
[task 2024-03-08T11:17:03.459Z] 11:17:03     INFO -    File "/home/cltbld/tasks/task_170989642618752/build/tests/raptor/raptor/benchmark.py", line 104, in _full_clone
[task 2024-03-08T11:17:03.459Z] 11:17:03     INFO -      subprocess.check_call(
[task 2024-03-08T11:17:03.459Z] 11:17:03     INFO -    File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
[task 2024-03-08T11:17:03.460Z] 11:17:03     INFO -      raise CalledProcessError(retcode, cmd)
[task 2024-03-08T11:17:03.460Z] 11:17:03     INFO -  subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation', '/tmp/tmpbmssby4g/performance-tests/perf-automation']' returned non-zero exit status 128.
[task 2024-03-08T11:17:03.507Z] 11:17:03     INFO - Return code: 1
[task 2024-03-08T11:17:03.508Z] 11:17:03  WARNING - setting return code to 1
[task 2024-03-08T11:17:03.508Z] 11:17:03     INFO - Copying Raptor results to upload dir:
[task 2024-03-08T11:17:03.508Z] 11:17:03     INFO - /home/cltbld/tasks/task_170989642618752/build/blobber_upload_dir/perfherder-data.json
[task 2024-03-08T11:17:03.508Z] 11:17:03     INFO - Copying raptor results from /home/cltbld/tasks/task_170989642618752/build/raptor.json to /home/cltbld/tasks/task_170989642618752/build/blobber_upload_dir/perfherder-data.json
[task 2024-03-08T11:17:03.508Z] 11:17:03 CRITICAL - Error copying results /home/cltbld/tasks/task_170989642618752/build/raptor.json to upload dir /home/cltbld/tasks/task_170989642618752/build/blobber_upload_dir/perfherder-data.json
[task 2024-03-08T11:17:03.508Z] 11:17:03     INFO - [Errno 2] No such file or directory: '/home/cltbld/tasks/task_170989642618752/build/raptor.json'
[task 2024-03-08T11:17:03.509Z] 11:17:03     INFO - Running post-action listener: _package_coverage_data
[task 2024-03-08T11:17:03.509Z] 11:17:03     INFO - Running post-action listener: _resource_record_post_action
[task 2024-03-08T11:17:03.509Z] 11:17:03     INFO - Running post-action listener: process_java_coverage_data
[task 2024-03-08T11:17:03.509Z] 11:17:03     INFO - Running post-action listener: stop_device
[task 2024-03-08T11:17:03.509Z] 11:17:03     INFO - [mozharness: 2024-03-08 11:17:03.509279Z] Finished run-tests step (success)
[task 2024-03-08T11:17:03.509Z] 11:17:03     INFO - Running post-run listener: _resource_record_post_run
[task 2024-03-08T11:17:03.669Z] 11:17:03     INFO - Total resource usage - Wall time: 101s; CPU: 1%; Read bytes: 86261760; Write bytes: 80281600; Read time: 144; Write time: 928
[task 2024-03-08T11:17:03.669Z] 11:17:03     INFO - TinderboxPrint: CPU usage<br/>0.9%
[task 2024-03-08T11:17:03.669Z] 11:17:03     INFO - TinderboxPrint: I/O read bytes / time<br/>86,261,760 / 144
[task 2024-03-08T11:17:03.669Z] 11:17:03     INFO - TinderboxPrint: I/O write bytes / time<br/>80,281,600 / 928
[task 2024-03-08T11:17:03.669Z] 11:17:03     INFO - TinderboxPrint: CPU idle<br/>801.9 (99.0%)
[task 2024-03-08T11:17:03.669Z] 11:17:03     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2024-03-08T11:17:03.670Z] 11:17:03     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-03-08T11:17:03.704Z] 11:17:03     INFO - run-tests - Wall time: 101s; CPU: 1%; Read bytes: 86261760; Write bytes: 80281600; Read time: 144; Write time: 928
[task 2024-03-08T11:17:04.366Z] 11:17:04  WARNING - returning nonzero exit status 1
[taskcluster 2024-03-08T11:17:04.414Z]    Exit Code: 1
[taskcluster 2024-03-08T11:17:04.414Z]    User Time: 1m25.18361s
[taskcluster 2024-03-08T11:17:04.414Z]  Kernel Time: 7.870919s
[taskcluster 2024-03-08T11:17:04.414Z]    Wall Time: 3m14.879118454s
[taskcluster 2024-03-08T11:17:04.414Z]       Result: FAILED
[taskcluster 2024-03-08T11:17:04.414Z] === Task Finished ===
[taskcluster 2024-03-08T11:17:04.414Z] Task Duration: 3m14.881087506s
[taskcluster 2024-03-08T11:17:04.533Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-06-06T11:11:44.690Z
[taskcluster 2024-03-08T11:17:04.821Z] 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/json" and expiry 2024-06-06T11:11:44.690Z
[taskcluster 2024-03-08T11:17:05.100Z] 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-06-06T11:11:44.690Z
[taskcluster 2024-03-08T11:17:05.380Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-06-06T11:11:44.690Z
[taskcluster:error] exit status 1
See Also: → 1860534
Duplicate of this bug: 1860534
Duplicate of this bug: 1832583

I don't believe there is much we can do, this seems to be a network issue that pops up every now and then e.g. Bug 1832583
For now it looks like it has subsided

Though maybe we can consider looking into increasing the buffer. I will file a bug for that

Flags: needinfo?(kshampur)
See Also: → 1885045
See Also: → 1804694
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Kash, does this need a chromedriver update? The ticket for 125 says that landed and 126 would be due in early June.

Flags: needinfo?(kshampur)

That chromedriver warning is a bit misleading unfortunately (and it appears even on passing chrome tasks). To answer your question an update isn't needed here. versions 124 and 125 chrome drivers were correctly fetched. The issue is still just the git checkout

anyhow, :aglavic is working on Bug 1804694 which should hopefully help with this

Flags: needinfo?(kshampur)

For context, that warning happens because we try getting a version using mozversion first, and then a custom method after that. We're hoping someone adds something for gathering the version number of those browsers to mozversion someday (might need to be us who does that :).

Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Perma [tier 2] subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation', '/tmp/tmpbmssby4g/performance-tests/perf-automation']' returned non... → Intermittent [tier 2] subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation] returned non-zero exit status 128.
Whiteboard: [stockwell disable-recommended] → [stockwell infra]
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Tier 1 link failure here.

Summary: Intermittent [tier 2] subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation] returned non-zero exit status 128. → Intermittent subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation] returned non-zero exit status 128.

Hi, there's been a recent spike in failures , could you please take a look? Thanks.

Flags: needinfo?(aglavic)
Summary: Intermittent subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation] returned non-zero exit status 128. → Frequent subprocess.CalledProcessError: Command '['git', 'clone', '-c', 'http.postBuffer=2147483648', '-c', 'core.autocrlf=false', 'https://github.com/mozilla/perf-automation] returned non-zero exit status 128.

Thanks, we're investigating!

Flags: needinfo?(aglavic)
Flags: needinfo?(aglavic)

Error seems to have not appeared in last week, I'm removing the needinfo for myself but going to continue work on this here: Bug 1804694

Flags: needinfo?(aglavic)
Status: REOPENED → RESOLVED
Closed: 1 year ago9 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.