Timeout with version 8.0.4 (git describe) #957

eachimei · 2023-10-13T08:31:43Z

This issue is similar to #913

But this time with the command git describe ...

* Creating venv isolated environment...

* Installing packages in isolated environment... (setuptools>=45, setuptools_scm[toml]>=6.2)

* Getting build dependencies for wheel...

Traceback (most recent call last):

  File "D:\GitHub-Runner\package-repo\.tox\release\lib\site-packages\pyproject_hooks\_in_process\_in_process.py", line 353, in <module>

    main()

  File "D:\GitHub-Runner\package-repo\.tox\release\lib\site-packages\pyproject_hooks\_in_process\_in_process.py", line 335, in main

    json_out['return_val'] = hook(**hook_input['kwargs'])

  File "D:\GitHub-Runner\package-repo\.tox\release\lib\site-packages\pyproject_hooks\_in_process\_in_process.py", line 118, in get_requires_for_build_wheel

    return hook(config_settings)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\build_meta.py", line 355, in get_requires_for_build_wheel

    return self._get_build_requires(config_settings, requirements=['wheel'])

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\build_meta.py", line 325, in _get_build_requires

    self.run_setup()

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\build_meta.py", line 341, in run_setup

    exec(code, locals())

  File "<string>", line 1, in <module>

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\__init__.py", line 103, in setup

    return distutils.core.setup(**attrs)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\_distutils\core.py", line 147, in setup

    _setup_distribution = dist = klass(attrs)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\dist.py", line 303, in __init__

    _Distribution.__init__(self, dist_attrs)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\_distutils\dist.py", line 283, in __init__

    self.finalize_options()

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools\dist.py", line 680, in finalize_options

    ep(self)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\_integration\setuptools.py", line 121, in infer_version

    _assign_version(dist, config)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\_integration\setuptools.py", line 53, in _assign_version

    maybe_version = _get_version(config, force_write_version_files=True)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\_get_version_impl.py", line 93, in _get_version

    parsed_version = parse_version(config)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\_get_version_impl.py", line 56, in parse_version

    or parse_scm_version(config)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\_get_version_impl.py", line 35, in parse_scm_version

    return _entrypoints.version_from_entrypoint(

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\_entrypoints.py", line 55, in version_from_entrypoint

    maybe_version: version.ScmVersion | None = fn(root, config=config)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\git.py", line 211, in parse

    return _git_parse_inner(

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\git.py", line 255, in _git_parse_inner

    version = version_from_describe(wd, config, describe_command)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\git.py", line 237, in version_from_describe

    describe_res = wd.default_describe()

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\git.py", line 157, in default_describe

    return run_git(DEFAULT_DESCRIBE[1:], self.path)

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\git.py", line 58, in run_git

    return _run(

  File "C:\Windows\Temp\build-env-cae0l3kt\lib\site-packages\setuptools_scm\_run_cmd.py", line 144, in run

    res = subprocess.run(

  File "D:\GitHub-Runner\_tool\Python\3.10.11\x64\lib\subprocess.py", line 505, in run

    stdout, stderr = process.communicate(input, timeout=timeout)

  File "D:\GitHub-Runner\_tool\Python\3.10.11\x64\lib\subprocess.py", line 1154, in communicate

    stdout, stderr = self._communicate(input, endtime, timeout)

  File "D:\GitHub-Runner\_tool\Python\3.10.11\x64\lib\subprocess.py", line 1546, in _communicate

    raise TimeoutExpired(self.args, orig_timeout)

subprocess.TimeoutExpired: Command '['git', '--git-dir', 'C:\\Windows\\Temp\\devpi-hpq_8ttl\\.git', 'describe', '--dirty', '--tags', '--long', '--match', '*[0-9]*']' timed out after 20 seconds

The text was updated successfully, but these errors were encountered:

ssbarnea · 2023-12-21T16:07:05Z

I was able to reproduce this issue in a consistent manner in particular case: running inside a container while redirecting the output to another command.

The issue also happens with olders setuptools-scm such 7.1.0 (shipped in fedora 39)

Reproduce

#!/bin/bash
python3 -m setuptools_scm | cat

Result with 8.0.4

Traceback (most recent call last):
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/__main__.py", line 6, in <module>
    main()
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/_cli.py", line 34, in main
    version = _get_version(config, force_write_version_files=False)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/_get_version_impl.py", line 93, in _get_version
    parsed_version = parse_version(config)
                     ^^^^^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/_get_version_impl.py", line 56, in parse_version
    or parse_scm_version(config)
       ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/_get_version_impl.py", line 35, in parse_scm_version
    return _entrypoints.version_from_entrypoint(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/_entrypoints.py", line 55, in version_from_entrypoint
    maybe_version: version.ScmVersion | None = fn(root, config=config)
                                               ^^^^^^^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/git.py", line 211, in parse
    return _git_parse_inner(
           ^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/git.py", line 255, in _git_parse_inner
    version = version_from_describe(wd, config, describe_command)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/git.py", line 233, in version_from_describe
    describe_res = run_git(describe_command[1:], wd.path)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/git.py", line 58, in run_git
    return _run(
           ^^^^^
  File "/code/venv/lib64/python3.12/site-packages/setuptools_scm/_run_cmd.py", line 144, in run
    res = subprocess.run(
          ^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/subprocess.py", line 550, in run
    stdout, stderr = process.communicate(input, timeout=timeout)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/subprocess.py", line 1209, in communicate
    stdout, stderr = self._communicate(input, endtime, timeout)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.12/subprocess.py", line 2109, in _communicate
    self._check_timeout(endtime, orig_timeout, stdout, stderr)
  File "/usr/lib64/python3.12/subprocess.py", line 1253, in _check_timeout
    raise TimeoutExpired(
subprocess.TimeoutExpired: Command '['git', '--git-dir', '/code/.git', 'describe', '--dirty', '--tags', '--long', '--match', 'v*.*']' timed out after 20 seconds

The repository where I get this is not even so large, but it has lots of tags matching the pattern, https://github.com/ansible/ansible-lint --

When running directly on my mac, the time git describe --dirty --tags --long --match 'v*.*' command is almost instant (0.01s), but inside the container with the code mounted it takes 4-7s, which is hundreds times slower but still within the 20 timeout.

Still when redirection is involved, it fails miserably. Because this command is part of the building of the RPMs, the entire process is now broken.

If the number of tags in the repository is what causes the issue, I could consider culling the very old ones. That is clearly not something that I would do happily because it could really affect some users that are using ancient versions via git.

Maybe someone has some ideas about what can be done to address this issue.

RonnyPfannschmidt · 2023-12-21T16:12:39Z

this is the first time i see this on unix with git ever - before only windows would fail on github due to sometimes taking >30 seconds to run hg commands

i never had a consistent reproducer, and its absolutely unclear why it happens

RonnyPfannschmidt · 2023-12-21T16:15:12Z

is the container you use using docker/podman machine? - its thinkable that the filesystem sync + vm play a role in setting this up

the reason why the 20 second timeout was added is that sometimes pipelines would hang for minutes or into job timeouts

how much time does the reproducer need ?

ssbarnea · 2023-12-21T16:23:50Z

@RonnyPfannschmidt My machine is an M1 mac (arch64) where I have both podman and docker engines installed, both containers do match the arch64 architecture, so they are expected to be fast.

Funny is that the slowness seems to happen only on podman one, docker seems fast at this operation.

Note: I am still debugging the issue, as you mentioned, is a very weird one and I bet that if it was widespread the issue tracker would be boiling. I am not questioning your timeout, I kinda guessed that without one it would be worse. 20s is big already, especially for computing a version number. I am wondering if that might be a regression with newer podman, i might have to reset the podman machine just to be sure.

Another question still remains,.... why would this git command prove to be so slow/intense? (disregarding the likely virtualization costs).

RonnyPfannschmidt · 2023-12-21T16:28:09Z

That's absolutely unclear to me

When it was only windows workers, it was easy blame FS pressure plus a miss config

Does it still happen when git is executed before?

What's the times in setuptools-scm debug logs

eachimei · 2024-01-01T08:57:02Z

I have more details on the Windows case I originally brought up:

The local git repository was copied from one location to another (on the same drive, same host), including the .git folder. It is guaranteed that the repository is in a clean, pristine state (no modifications etc.). One would have expected the "old" and "new" location to be in the exact same state. This is happening as part of a devpi upload call.
The repository uses git-lfs and has a significant amount of large LFS-tracked files. It is guaranteed that before the copy mentioned in previous bullet, git lfs pull has been completed successfully: all LFS files are fully present (actual files, not pointers).
When git describe ... (or for that matter, even a simple git status) is running in the new location of the repo, git trace shows Refreshing index... message, and git-lfs subprocess kicks in (filter-process) and if I'm not mistaken it actually reaches the remote. It is running for relatively long time and this is the root-cause for the git describe timeout.
I think that git somehow notices the location change and invalidates some internal git caches. As a result, it pulls all LFS files all over again in the new local repo location.

eachimei · 2024-01-03T11:39:02Z

As a workaround (since currently there is no way to modify the default git describe ... timeout), I added an in-tree build-backend that calls git status (without a timeout/with a sufficiently long timeout value):

pyproject.toml:

[build-system]
requires = ["setuptools>=45", "setuptools_scm[toml]>=6.2"]
backend-path = ["build_backend"]
# workaround for https://github.com/pypa/setuptools_scm/issues/957
build-backend = "backend"

[tool.setuptools_scm]

build_backend/backend.py:

import os
import subprocess
from setuptools.build_meta import get_requires_for_build_wheel as \
    _get_requires_for_build_wheel
from setuptools.build_meta import *  # noqa: F403, F401


def _refresh_git_index():
    # workaround for setuptools-scm timeout issue:
    # https://github.com/pypa/setuptools_scm/issues/957
    if not os.path.isdir(".git"):
        print(f"unable to find .git directory (cwd: {os.getcwd()})")
        return
    # ensure that by the time setuptools_scm calls `git describe` with timeout, the local index is already refreshed:
    subprocess.call("git status")  


def get_requires_for_build_wheel(*args, **kwargs):
    _refresh_git_index()
    return _get_requires_for_build_wheel(*args, **kwargs)

eachimei · 2024-01-03T11:41:17Z

Why not introduce a configurable timeout? Proposal:

pyproject.toml :

...

[tool.setuptools_scm]
# set git commands timeout to 100 seconds:
git_timeout = 100

or a finer-granularity for the different git commands...
Thoughts?

RonnyPfannschmidt · 2024-01-03T12:19:58Z

would it be sufficient to have the scm status command/help command be executed with a minute timeout + some loggingin case it takes longer

(then setuptools_scm would log a few errors noting the timeout/delay)

eachimei · 2024-01-03T12:36:00Z

That's definitely an improvement. However, I wonder if it won't fail to scale: since apparently git index refresh depends (in such LFS cases) on pulling files from the remote (still puzzled about this, but this is how git behaves...) - it might take longer in slow network conditions or large amounts of data or slow file-systems. Therefore, it feels to me that a common and reasonable timeout should be a default, but the user should ultimately have the option to configure the timeout value based on his/hers repo and network conditions.

RonnyPfannschmidt · 2024-01-03T16:58:37Z

There's a limit to how much user/setup inflicted mess setuptools-scm ought to handle

For more timeout intensity stuff people ought to handle it by running their cache refreshing commands before the build

eachimei · 2024-01-03T17:42:36Z

Agreed, I'm with you on that; but in this case the user is running devpi and that creates a temporary local working copy (similar to how build creates a temporary venv to operate on) and the build process runs in there - all at once, as a single flow. Therefore, the user doesn't have the opportunity to refresh git cache in that temporary location...
The custom build-backend works (already verified), but it's a workaround and not an elegant solution. We can live with that of course, but others might not reach that...
While setuptools-scm shouldn't make up for every environment issue, I do think that hard-coded timeout values might be too strict as we learn how sensitive it may be to performance-related aspects and repository content.

eachimei · 2024-01-03T17:47:26Z

If you're onboard, I'll be glad to try and contribute that feature (if that helps)

RonnyPfannschmidt · 2024-01-03T17:57:52Z

Im curious about the solution you have in mind

eachimei · 2024-01-04T13:01:25Z

I was thinking on an environment variable override (https://setuptools-scm.readthedocs.io/en/latest/overrides/)

Rationale: the matter we discuss is mostly impacted by environment aspects (network, file-system performance vs. repository content, configuration and size). Therefore, for package maintainers it sounds wrong to have the timeout override as part of pyproject.toml since the timeout value might vary on different build environments (the same argument goes for entry-point hooks). However, as an environment-variable override, it is very easy to set it up according to the needs. For example, tox.ini (setenv) or GitHub Workflow env: section or manually setting the variable in a one-off shell...

Variable scope/impact: should we go with a very "wide" definition (e.g. ..._SCM_TIMEOUT)? Or git-specific (e.g. ...GIT_TIMEOUT)? or even a finer granularity per command (e.g. ...GIT_DESCRIBE_TIMEOUT)?
Sounds to me that the middle ground of general Git timeout override makes sense. For example, if SETUPTOOLS_SCM_GIT_TIMEOUT is set, this timeout value is going to be used to all git-related commands. When not set, the existing default timeout values will be used.

Looking forward to hearing your thoughts :)

eachimei · 2024-01-04T13:09:55Z

A partially related update: I think I see how devpi itself can be improved to create the temporary local working-copy with the right metadata preservation (e.g. timestamps, permissions) so Git integrity check won't "get upset".
Currently devpi uses shutil.copy2 directly and indirectly (copytree default copy function). While copy2 should preserve most metadata, apparently it's not sufficient. The Git-recommended way to copy to a new local working-copy is using git clone <src_local_repo> <dst_local_repo> and this creates a clean copy without metadata issues. I tested this approach and indeed it looks good. I'll go ahead and propose that to devpi...

RonnyPfannschmidt · 2024-01-05T12:27:15Z

i'm adding SETUPTOOLS_SCM_SUBPROCESS_TIMEOUT as env var

eachimei · 2024-01-05T17:38:14Z

Thank you!

RonnyPfannschmidt added a commit to RonnyPfannschmidt/setuptools_scm that referenced this issue Jan 5, 2024

fix pypa#957 - add subprocess timeout

fb9c040

RonnyPfannschmidt mentioned this issue Jan 5, 2024

cleanups + bugfixes #996

Merged

RonnyPfannschmidt added a commit to RonnyPfannschmidt/setuptools_scm that referenced this issue Jan 5, 2024

fix pypa#957 - add subprocess timeout

03f31d1

RonnyPfannschmidt added a commit to RonnyPfannschmidt/setuptools_scm that referenced this issue Jan 8, 2024

fixup pypa#957 - timeout passover for git

43e3bcd

RonnyPfannschmidt added a commit to RonnyPfannschmidt/setuptools_scm that referenced this issue Jan 8, 2024

fixup pypa#957 - timeout passover for git

d705a92

RonnyPfannschmidt added a commit to RonnyPfannschmidt/setuptools_scm that referenced this issue Feb 13, 2024

fix pypa#957 - add subprocess timeout

2ac4f08

RonnyPfannschmidt added a commit to RonnyPfannschmidt/setuptools_scm that referenced this issue Feb 13, 2024

fixup pypa#957 - timeout passover for git

6c8c164

RonnyPfannschmidt closed this as completed in #996 Feb 15, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timeout with version 8.0.4 (git describe) #957

Timeout with version 8.0.4 (git describe) #957

eachimei commented Oct 13, 2023

ssbarnea commented Dec 21, 2023

RonnyPfannschmidt commented Dec 21, 2023

RonnyPfannschmidt commented Dec 21, 2023

ssbarnea commented Dec 21, 2023

RonnyPfannschmidt commented Dec 21, 2023

eachimei commented Jan 1, 2024

eachimei commented Jan 3, 2024 •

edited

Loading

eachimei commented Jan 3, 2024

RonnyPfannschmidt commented Jan 3, 2024

eachimei commented Jan 3, 2024

RonnyPfannschmidt commented Jan 3, 2024

eachimei commented Jan 3, 2024

eachimei commented Jan 3, 2024

RonnyPfannschmidt commented Jan 3, 2024

eachimei commented Jan 4, 2024

eachimei commented Jan 4, 2024

RonnyPfannschmidt commented Jan 5, 2024

eachimei commented Jan 5, 2024

Timeout with version 8.0.4 (git describe) #957

Timeout with version 8.0.4 (git describe) #957

Comments

eachimei commented Oct 13, 2023

ssbarnea commented Dec 21, 2023

Result with 8.0.4

RonnyPfannschmidt commented Dec 21, 2023

RonnyPfannschmidt commented Dec 21, 2023

ssbarnea commented Dec 21, 2023

RonnyPfannschmidt commented Dec 21, 2023

eachimei commented Jan 1, 2024

eachimei commented Jan 3, 2024 • edited Loading

eachimei commented Jan 3, 2024

RonnyPfannschmidt commented Jan 3, 2024

eachimei commented Jan 3, 2024

RonnyPfannschmidt commented Jan 3, 2024

eachimei commented Jan 3, 2024

eachimei commented Jan 3, 2024

RonnyPfannschmidt commented Jan 3, 2024

eachimei commented Jan 4, 2024

eachimei commented Jan 4, 2024

RonnyPfannschmidt commented Jan 5, 2024

eachimei commented Jan 5, 2024

eachimei commented Jan 3, 2024 •

edited

Loading