GIT_TRACE=1 breaks tsrc sync

[pdecat]

When GIT_TRACE=1 is set, tsrc init works fine but tsrc sync breaks when reading branch information.

Environment

• Output of tsrc --version: tsrc 2.7.1
• Operating system: Ubuntu 23.10

Command you ran

While investigating some issues synchronizing some repositories, I made git more verbose with GIT_TRACE=1, e.g.:

$ export GIT_TRACE=1
$ mkdir tsrc-test
$ cd tsrc-test
$ tsrc init https://github.com/pdecat/tsrc-test-manifest.git
$ tsrc sync

Actual output

:: Using workspace in /home/patrick/workspaces/thirdparty/tsrc-test
=> Updating manifest
$ git remote set-url origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:53.673878 git.c:463               trace: built-in: git remote set-url origin https://github.com/pdecat/tsrc-test-manifest.git
$ git fetch
12:01:53.679346 git.c:463               trace: built-in: git fetch
12:01:53.679870 run-command.c:659       trace: run_command: GIT_DIR=.git git remote-https origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:53.681311 git.c:749               trace: exec: git-remote-https origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:53.681358 run-command.c:659       trace: run_command: git-remote-https origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:54.012960 run-command.c:659       trace: run_command: git rev-list --objects --stdin --not --exclude-hidden=fetch --all --quiet --alternate-refs
12:01:54.018654 run-command.c:1523      run_processes_parallel: preparing to run up to 1 tasks
12:01:54.018675 run-command.c:1551      run_processes_parallel: done
12:01:54.018685 run-command.c:659       trace: run_command: git maintenance run --auto --no-quiet
12:01:54.020109 git.c:463               trace: built-in: git maintenance run --auto --no-quiet
$ git checkout -B main
12:01:54.023018 git.c:463               trace: built-in: git checkout -B main
Reset branch 'main'
Your branch is up to date with 'origin/main'.
$ git branch main --set-upstream-to origin/main
12:01:54.031756 git.c:463               trace: built-in: git branch main --set-upstream-to origin/main
branch 'main' set up to track 'origin/main'.
$ git reset --hard origin/main
12:01:54.046262 git.c:463               trace: built-in: git reset --hard origin/main
HEAD is now at 823d55f Add manifest.yml
=> Cloning missing repos
=> Configuring remotes
$ git remote set-url origin git@github.com:your-tools/tsrc.git
12:01:54.060947 git.c:463               trace: built-in: git remote set-url origin git@github.com:your-tools/tsrc.git
* (1/1) ok tsrc
tsrc: remote 'origin' set to 'git@github.com:your-tools/tsrc.git'
=> Synchronizing repos
* (1/1) ok tsrc
=> Updated repos:
tsrc on 12:01:54.418690 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
main
-----------------------------------------------------------------------------------------------------
12:01:54.426679 git.c:463               trace: built-in: git merge --ff-only '@{upstream}'
Already up to date.
12:01:54.430160 git.c:749               trace: exec: git-submodule update --init --recursive
12:01:54.430188 run-command.c:659       trace: run_command: git-submodule update --init --recursive
12:01:54.440474 git.c:463               trace: built-in: git rev-parse --git-dir
12:01:54.442123 git.c:463               trace: built-in: git rev-parse --git-path objects
12:01:54.444911 git.c:463               trace: built-in: git rev-parse --show-prefix
12:01:54.446571 git.c:463               trace: built-in: git rev-parse --show-toplevel
12:01:54.450040 git.c:463               trace: built-in: git submodule--helper update --recursive --init --
12:01:54.450507 run-command.c:1523      run_processes_parallel: preparing to run up to 1 tasks
12:01:54.450520 run-command.c:1551      run_processes_parallel: done
Error: Failed to synchronize the following repos:
* tsrc : Current branch: '12:01:54.418690 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
main' does not match expected branch: 'main'

Expected result

Just like a normal tsrc sync output, but with the native git trace messages shown:

:: Using workspace in /home/patrick/workspaces/thirdparty/tsrc-test
=> Updating manifest
$ git remote set-url origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:53.673878 git.c:463               trace: built-in: git remote set-url origin https://github.com/pdecat/tsrc-test-manifest.git
$ git fetch
12:01:53.679346 git.c:463               trace: built-in: git fetch
12:01:53.679870 run-command.c:659       trace: run_command: GIT_DIR=.git git remote-https origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:53.681311 git.c:749               trace: exec: git-remote-https origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:53.681358 run-command.c:659       trace: run_command: git-remote-https origin https://github.com/pdecat/tsrc-test-manifest.git
12:01:54.012960 run-command.c:659       trace: run_command: git rev-list --objects --stdin --not --exclude-hidden=fetch --all --quiet --alternate-refs
12:01:54.018654 run-command.c:1523      run_processes_parallel: preparing to run up to 1 tasks
12:01:54.018675 run-command.c:1551      run_processes_parallel: done
12:01:54.018685 run-command.c:659       trace: run_command: git maintenance run --auto --no-quiet
12:01:54.020109 git.c:463               trace: built-in: git maintenance run --auto --no-quiet
$ git checkout -B main
12:01:54.023018 git.c:463               trace: built-in: git checkout -B main
Reset branch 'main'
Your branch is up to date with 'origin/main'.
$ git branch main --set-upstream-to origin/main
12:01:54.031756 git.c:463               trace: built-in: git branch main --set-upstream-to origin/main
branch 'main' set up to track 'origin/main'.
$ git reset --hard origin/main
12:01:54.046262 git.c:463               trace: built-in: git reset --hard origin/main
HEAD is now at 823d55f Add manifest.yml
=> Cloning missing repos
=> Configuring remotes
$ git remote set-url origin git@github.com:your-tools/tsrc.git
12:01:54.060947 git.c:463               trace: built-in: git remote set-url origin git@github.com:your-tools/tsrc.git
* (1/1) ok tsrc
tsrc: remote 'origin' set to 'git@github.com:your-tools/tsrc.git'
=> Synchronizing repos
* (1/1) ok tsrc
:: Workspace synchronized

Notes

Many tests are also broken when the GIT_TRACE environment variable is set.

Without it

$ git config --global protocol.file.allow always && poetry run pytest && git config --global --unset protocol.file.allow
===================================================================================== test session starts ======================================================================================
platform linux -- Python 3.11.6, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/patrick/workspaces/tsrc
plugins: cov-2.12.1, forked-1.4.0, xdist-1.34.0
collected 162 items

tsrc/test/test_config.py ...                                                                                                                                                             [  1%]
tsrc/test/test_executor.py ......                                                                                                                                                        [  5%]
tsrc/test/test_file_system.py ......                                                                                                                                                     [  9%]
tsrc/test/test_git_status.py ............                                                                                                                                                [ 16%]
tsrc/test/test_groups.py ........                                                                                                                                                        [ 21%]
tsrc/test/test_manifest.py ............                                                                                                                                                  [ 29%]
tsrc/test/test_resolve_repos.py .........                                                                                                                                                [ 34%]
tsrc/test/test_workspace_config.py .                                                                                                                                                     [ 35%]
tsrc/test/cli/test_apply_manifest.py .                                                                                                                                                   [ 35%]
tsrc/test/cli/test_cli.py .....                                                                                                                                                          [ 38%]
tsrc/test/cli/test_env_setter.py ...                                                                                                                                                     [ 40%]
tsrc/test/cli/test_foreach.py ...........                                                                                                                                                [ 47%]
tsrc/test/cli/test_init.py ......................                                                                                                                                        [ 61%]
tsrc/test/cli/test_log.py ....                                                                                                                                                           [ 63%]
tsrc/test/cli/test_main.py ...                                                                                                                                                           [ 65%]
tsrc/test/cli/test_shallow_clones.py ..                                                                                                                                                  [ 66%]
tsrc/test/cli/test_status.py ........                                                                                                                                                    [ 71%]
tsrc/test/cli/test_sync.py ...................................                                                                                                                           [ 93%]
tsrc/test/helpers/test_git_server.py ...........                                                                                                                                         [100%]

With it

$ export GIT_TRACE=1
$ git config --global protocol.file.allow always && poetry run pytest && git config --global --unset protocol.file.allow
11:01:29.889125 git.c:463               trace: built-in: git config --global protocol.file.allow always
===================================================================================== test session starts ======================================================================================
platform linux -- Python 3.11.6, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/patrick/workspaces/tsrc
plugins: cov-2.12.1, forked-1.4.0, xdist-1.34.0
collected 162 items

tsrc/test/test_config.py ...                                                                                                                                                             [  1%]
tsrc/test/test_executor.py ......                                                                                                                                                        [  5%]
tsrc/test/test_file_system.py ......                                                                                                                                                     [  9%]
tsrc/test/test_git_status.py .F.FFFF.....                                                                                                                                                [ 16%]
tsrc/test/test_groups.py ........                                                                                                                                                        [ 21%]
tsrc/test/test_manifest.py ............                                                                                                                                                  [ 29%]
tsrc/test/test_resolve_repos.py .........                                                                                                                                                [ 34%]
tsrc/test/test_workspace_config.py .                                                                                                                                                     [ 35%]
tsrc/test/cli/test_apply_manifest.py .                                                                                                                                                   [ 35%]
tsrc/test/cli/test_cli.py .....                                                                                                                                                          [ 38%]
tsrc/test/cli/test_env_setter.py F..                                                                                                                                                     [ 40%]
tsrc/test/cli/test_foreach.py ...........                                                                                                                                                [ 47%]
tsrc/test/cli/test_init.py FF........F.FF...FFFF.                                                                                                                                        [ 61%]
tsrc/test/cli/test_log.py F...                                                                                                                                                           [ 63%]
tsrc/test/cli/test_main.py ...                                                                                                                                                           [ 65%]
tsrc/test/cli/test_shallow_clones.py F.                                                                                                                                                  [ 66%]
tsrc/test/cli/test_status.py FFFFF...                                                                                                                                                    [ 71%]
tsrc/test/cli/test_sync.py FF.FFFFFFFFF.FFFFFFFF..FFFFFFFFFFFF                                                                                                                           [ 93%]
tsrc/test/helpers/test_git_server.py .F......F..                                                                                                                                         [100%]

=========================================================================================== FAILURES ===========================================================================================
...
=================================================================================== short test summary info ====================================================================================
FAILED tsrc/test/test_git_status.py::test_clean_on_master - AssertionError: assert '11:01:30.727... HEAD\nmaster' == 'master'
FAILED tsrc/test/test_git_status.py::test_behind_1_commit - assert 1 == 0
FAILED tsrc/test/test_git_status.py::test_ahead_2_commits - assert 3 == 2
FAILED tsrc/test/test_git_status.py::test_on_sha1 - AssertionError: assert '11:01:30.958166 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD\nHEAD' is None
FAILED tsrc/test/test_git_status.py::test_on_tag - AssertionError: assert '11:01:30.997...at HEAD\nv0.1' == 'v0.1'
FAILED tsrc/test/cli/test_env_setter.py::test_set_project_dest_and_branch - AssertionError: assert '11:01:31.336... HEAD\nmaster' == 'master'
FAILED tsrc/test/cli/test_init.py::test_init_manifest_head_is_master - AssertionError: assert '11:01:33.044... HEAD\nmaster' == 'master'
FAILED tsrc/test/cli/test_init.py::test_init_manifest_head_is_main - AssertionError: assert '11:01:33.142...ef HEAD\nmain' == 'main'
FAILED tsrc/test/cli/test_init.py::test_uses_correct_branch_for_repo - AssertionError: assert '11:01:33.895...ef HEAD\nnext' == 'next'
FAILED tsrc/test/cli/test_init.py::test_resets_to_tag - AssertionError: assert '11:01:34.091...1d77681be8e46' == '11:01:34.093...1d77681be8e46'
FAILED tsrc/test/cli/test_init.py::test_resets_to_sha1 - AssertionError: assert '39b4a08bae38...1d77681be8e46' == '11:01:34.202...1d77681be8e46'
FAILED tsrc/test/cli/test_init.py::test_no_remote_named_origin - tsrc.git.GitCommandError: `git checkout -B 11:01:34.624984 git.c:463               trace: built-in: git rev-parse --abbrev-r...
FAILED tsrc/test/cli/test_init.py::test_repo_default_branch_not_master - AssertionError: assert '11:01:34.814...f HEAD\ndevel' == 'devel'
FAILED tsrc/test/cli/test_init.py::test_several_remotes - AssertionError: assert '11:01:34.918...@upstream.com' == 'git@upstream.com'
FAILED tsrc/test/cli/test_init.py::test_singular_remote - AssertionError: assert '11:01:35.019... show\norigin' == 'origin'
FAILED tsrc/test/cli/test_log.py::test_happy - tsrc.git.GitCommandError: `git checkout -B 11:01:35.234997 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_shallow_clones.py::test_shallow_clones - AssertionError: assert False
FAILED tsrc/test/cli/test_status.py::test_status_happy - AssertionError: assert None
FAILED tsrc/test/cli/test_status.py::test_status_dirty - AssertionError: assert None
FAILED tsrc/test/cli/test_status.py::test_status_incorrect_branch - AssertionError: assert None
FAILED tsrc/test/cli/test_status.py::test_status_not_on_any_branch - AssertionError: assert None
FAILED tsrc/test/cli/test_status.py::test_status_on_tag - AssertionError: assert None
FAILED tsrc/test/cli/test_sync.py::test_sync_happy - tsrc.git.GitCommandError: `git checkout -B 11:01:36.959615 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_sync.py::test_sync_sequential - tsrc.git.GitCommandError: `git checkout -B 11:01:37.115536 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_sync.py::test_sync_on_bare_repo - AssertionError
FAILED tsrc/test/cli/test_sync.py::test_sync_finds_root - tsrc.git.GitCommandError: `git checkout -B 11:01:37.518857 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_sync.py::test_new_repo_added_to_manifest - tsrc.git.GitCommandError: `git checkout -B 11:01:37.647449 git.c:463               trace: built-in: git rev-parse --abbr...
FAILED tsrc/test/cli/test_sync.py::test_switching_manifest_branch - tsrc.git.GitCommandError: `git checkout -B 11:01:37.783324 git.c:463               trace: built-in: git rev-parse --abbre...
FAILED tsrc/test/cli/test_sync.py::test_sync_not_on_master - AssertionError: foo should have been updated
FAILED tsrc/test/cli/test_sync.py::test_sync_with_force - tsrc.git.GitCommandError: `git checkout -B 11:01:38.086144 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_sync.py::test_sync_discards_local_manifest_changes - tsrc.git.GitCommandError: `git checkout -B 11:01:38.215166 git.c:463               trace: built-in: git rev-pa...
FAILED tsrc/test/cli/test_sync.py::test_sync_with_no_update_manifest_flag_leaves_changes - tsrc.workspace.SyncError
FAILED tsrc/test/cli/test_sync.py::test_copies_are_up_to_date - tsrc.git.GitCommandError: `git checkout -B 11:01:38.565998 git.c:463               trace: built-in: git rev-parse --abbrev-re...
FAILED tsrc/test/cli/test_sync.py::test_update_symlink - tsrc.git.GitCommandError: `git checkout -B 11:01:38.803063 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_sync.py::test_changing_branch - AssertionError: assert None
FAILED tsrc/test/cli/test_sync.py::test_changing_branch_with_correct_branch - tsrc.git.GitCommandError: `git checkout -B 11:01:39.074571 git.c:463               trace: built-in: git rev-par...
FAILED tsrc/test/cli/test_sync.py::test_changing_branch_with_correct_branch_but_dirty_repo - AssertionError: assert None
FAILED tsrc/test/cli/test_sync.py::test_tags_are_not_updated - tsrc.git.GitCommandError: `git checkout -B 11:01:39.353913 git.c:463               trace: built-in: git rev-parse --abbrev-ref...
FAILED tsrc/test/cli/test_sync.py::test_sha1s_are_not_updated - tsrc.git.GitCommandError: `git checkout -B 11:01:39.486848 git.c:463               trace: built-in: git rev-parse --abbrev-re...
FAILED tsrc/test/cli/test_sync.py::test_tags_are_updated_when_clean - tsrc.git.GitCommandError: `git checkout -B 11:01:39.620493 git.c:463               trace: built-in: git rev-parse --abb...
FAILED tsrc/test/cli/test_sync.py::test_sha1s_are_updated_when_clean - tsrc.git.GitCommandError: `git checkout -B 11:01:39.768991 git.c:463               trace: built-in: git rev-parse --ab...
FAILED tsrc/test/cli/test_sync.py::test_sync_uses_group_from_config_by_default - tsrc.git.GitCommandError: `git checkout -B 11:01:40.171975 git.c:463               trace: built-in: git rev-...
FAILED tsrc/test/cli/test_sync.py::test_fetch_additional_remotes - tsrc.git.GitCommandError: `git checkout -B 11:01:40.314389 git.c:463               trace: built-in: git rev-parse --abbrev...
FAILED tsrc/test/cli/test_sync.py::test_adding_remotes - tsrc.git.GitCommandError: `git checkout -B 11:01:40.466323 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_sync.py::test_changing_remote_url - tsrc.git.GitCommandError: `git checkout -B 11:01:40.622924 git.c:463               trace: built-in: git rev-parse --abbrev-ref ...
FAILED tsrc/test/cli/test_sync.py::test_sync_with_singular_remote - tsrc.git.GitCommandError: `git checkout -B 11:01:40.767656 git.c:463               trace: built-in: git rev-parse --abbre...
FAILED tsrc/test/cli/test_sync.py::TestSyncWithGroups::test_ignore_other_groups - tsrc.git.GitCommandError: `git checkout -B 11:01:40.903932 git.c:463               trace: built-in: git rev...
FAILED tsrc/test/cli/test_sync.py::TestSyncWithGroups::test_honors_new_included_groups - tsrc.git.GitCommandError: `git checkout -B 11:01:41.080987 git.c:463               trace: built-in: ...
FAILED tsrc/test/cli/test_sync.py::TestSyncWithGroups::test_can_use_new_group - tsrc.git.GitCommandError: `git checkout -B 11:01:41.251780 git.c:463               trace: built-in: git rev-p...
FAILED tsrc/test/cli/test_sync.py::TestSyncWithGroups::test_non_existing_group - AssertionError
FAILED tsrc/test/cli/test_sync.py::TestSyncWithGroups::test_group_not_cloned - tsrc.git.GitCommandError: `git checkout -B 11:01:41.548030 git.c:463               trace: built-in: git rev-pa...
FAILED tsrc/test/cli/test_sync.py::test_update_submodules - tsrc.git.GitCommandError: `git checkout -B 11:01:41.738887 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/cli/test_sync.py::test_ignored_submodules - tsrc.git.GitCommandError: `git checkout -B 11:01:41.954115 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
FAILED tsrc/test/helpers/test_git_server.py::test_can_set_remote_head - AssertionError: assert '11:01:42.103...ef HEAD\nmain' == 'main'
FAILED tsrc/test/helpers/test_git_server.py::test_default_branch_devel - AssertionError: assert '11:01:42.320...f HEAD\ndevel' == 'devel'
=============================================================================== 55 failed, 107 passed in 12.34s ================================================================================

Single test with full details

$ export GIT_TRACE=1
$ git config --global protocol.file.allow always && poetry run pytest -k test_default_branch_devel  && git config --global --unset protocol.file.allow
11:12:29.937339 git.c:463               trace: built-in: git config --global protocol.file.allow always
===================================================================================== test session starts ======================================================================================
platform linux -- Python 3.11.6, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/patrick/workspaces/tsrc
plugins: cov-2.12.1, forked-1.4.0, xdist-1.34.0
collected 162 items / 161 deselected / 1 selected

tsrc/test/helpers/test_git_server.py F                                                                                                                                                   [100%]

=========================================================================================== FAILURES ===========================================================================================
__________________________________________________________________________________ test_default_branch_devel ___________________________________________________________________________________

workspace_path = PosixPath('/tmp/pytest-of-patrick/pytest-5/test_default_branch_devel0/work'), git_server = <tsrc.test.helpers.git_server.GitServer object at 0x7f09cc77ec50>

    def test_default_branch_devel(workspace_path: Path, git_server: GitServer) -> None:
        foo_url = git_server.add_repo("foo", default_branch="devel")
        run_git(workspace_path, "clone", foo_url)
        foo_path = workspace_path / "foo"
        cloned_branch = get_current_branch(foo_path)
>       assert cloned_branch == "devel"
E       AssertionError: assert '11:12:30.751...f HEAD\ndevel' == 'devel'
E         + 11:12:30.751225 git.c:463               trace: built-in: git rev-parse --abbrev-ref HEAD
E           devel

tsrc/test/helpers/test_git_server.py:98: AssertionError
------------------------------------------------------------------------------------- Captured stdout call -------------------------------------------------------------------------------------
$ git clone file:///tmp/pytest-of-patrick/pytest-5/test_default_branch_devel0/srv/bare/foo
------------------------------------------------------------------------------------- Captured stderr call -------------------------------------------------------------------------------------
11:12:30.725575 git.c:463               trace: built-in: git clone file:///tmp/pytest-of-patrick/pytest-5/test_default_branch_devel0/srv/bare/foo
Cloning into 'foo'...
11:12:30.727644 run-command.c:659       trace: run_command: unset GIT_DIR; GIT_PROTOCOL=version=2 'git-upload-pack '\''/tmp/pytest-of-patrick/pytest-5/test_default_branch_devel0/srv/bare/foo'\'''
11:12:30.730376 git.c:463               trace: built-in: git upload-pack /tmp/pytest-of-patrick/pytest-5/test_default_branch_devel0/srv/bare/foo
11:12:30.731923 run-command.c:659       trace: run_command: git pack-objects --revs --thin --stdout --delta-base-offset
11:12:30.731953 run-command.c:659       trace: run_command: git index-pack --stdin --fix-thin '--keep=fetch-pack 3551423 on poulpy' --check-self-contained-and-connected
11:12:30.733207 git.c:463               trace: built-in: git index-pack --stdin --fix-thin '--keep=fetch-pack 3551423 on poulpy' --check-self-contained-and-connected
remote: 11:12:30.733466 git.c:463               trace: built-in: git pack-objects --revs --thin --stdout --delta-base-offset
11:12:30.744990 run-command.c:659       trace: run_command: git rev-list --objects --stdin --not --all --quiet --alternate-refs
11:12:30.746641 git.c:463               trace: built-in: git rev-list --objects --stdin --not --all --quiet --alternate-refs
=================================================================================== short test summary info ====================================================================================
FAILED tsrc/test/helpers/test_git_server.py::test_default_branch_devel - AssertionError: assert '11:12:30.751...f HEAD\ndevel' == 'devel'
============================================================================== 1 failed, 161 deselected in 0.28s ===============================================================================