clone: silently stuck on transferkey

[yarikoptic]

Originally was done using datalad clone but that one was silent, so ran directly with GIT_TRACE to hope to gain some clue, but didn't really, so I Ctrl-C'ed it

❯ GIT_TRACE=1 git clone osf://gvjbn

```shell ❯ GIT_TRACE=1 git clone osf://gvjbn 15:58:21.457958 git.c:463 trace: built-in: git clone osf://gvjbn Cloning into 'gvjbn'... 15:58:21.461340 run-command.c:659 trace: run_command: git remote-osf origin osf://gvjbn 15:58:21.463788 git.c:749 trace: exec: git-remote-osf origin osf://gvjbn 15:58:21.463834 run-command.c:659 trace: run_command: git-remote-osf origin osf://gvjbn 15:58:21.486704 git.c:463 trace: built-in: git describe --tags --dirty --always --long --match '[[:digit:]]*' 15:58:21.488953 git.c:463 trace: built-in: git rev-parse HEAD 15:58:21.490061 git.c:463 trace: built-in: git rev-parse --abbrev-ref HEAD 15:58:21.491483 git.c:463 trace: built-in: git show -s '--format=%ci' HEAD ^Cobject address : 0x7f7cda732440 object refcount : 2 object type : 0x9e5980 object type name: KeyboardInterrupt object repr : KeyboardInterrupt() lost sys.stderr ```

rerunning after complete redo of virtualenv and thus all fresh updates to datalad etc:

❯ DATALAD_LOG_LEVEL=debug GIT_TRACE=1 git clone osf://gvjbn

```shell ❯ DATALAD_LOG_LEVEL=debug GIT_TRACE=1 git clone osf://gvjbn 16:05:07.654502 git.c:463 trace: built-in: git clone osf://gvjbn Cloning into 'gvjbn'... 16:05:07.657304 run-command.c:659 trace: run_command: git remote-osf origin osf://gvjbn 16:05:07.659415 git.c:749 trace: exec: git-remote-osf origin osf://gvjbn 16:05:07.659466 run-command.c:659 trace: run_command: git-remote-osf origin osf://gvjbn 16:05:07.684729 git.c:463 trace: built-in: git describe --tags --dirty --always --long --match '[[:digit:]]*' 16:05:07.687019 git.c:463 trace: built-in: git rev-parse HEAD 16:05:07.688120 git.c:463 trace: built-in: git rev-parse --abbrev-ref HEAD 16:05:07.689517 git.c:463 trace: built-in: git show -s '--format=%ci' HEAD [DEBUG] Enable posting DataLad config overrides CLI/ENV as GIT_CONFIG items in process ENV [DEBUG] Run ['git', 'version'] (protocol_class=StdOutErrCapture) (cwd=None) [DEBUG] Finished ['git', 'version'] with status 0 ... [DEBUG] Run ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'annex', 'init'] (protocol_class=GeneratorStdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [Level 11] stderr| 16:05:07.841237 git.c:749 trace: exec: git-annex init [Level 11] stderr| 16:05:07.841260 run-command.c:659 trace: run_command: git-annex init [Level 11] stderr| 16:05:07.844741 git.c:463 trace: built-in: git config --null --list [Level 11] stderr| 16:05:07.848830 git.c:463 trace: built-in: git show-ref --hash refs/heads/git-annex [Level 11] stderr| 16:05:07.850199 git.c:463 trace: built-in: git show-ref --verify -q refs/remotes/origin/git-annex [Level 11] stderr| 16:05:07.852587 git.c:463 trace: built-in: git update-index -z --index-info [Level 11] stderr| 16:05:07.859731 git.c:463 trace: built-in: git write-tree [Level 11] stderr| 16:05:07.862192 git.c:463 trace: built-in: git commit-tree 4b825dc642cb6eb9a060e54bf8d69288fbee4904 --no-gpg-sign [Level 11] stderr| 16:05:07.865301 git.c:463 trace: built-in: git update-ref refs/heads/git-annex 59c9e1aeae5641af42a9132de0f1c5c1ccf6d4c0 [Level 11] stderr| 16:05:07.867777 git.c:463 trace: built-in: git config annex.uuid 67d613e2-c811-4f2c-9fea-3bf391ff4a5c [Level 11] stderr| 16:05:07.869669 git.c:463 trace: built-in: git config --null --list [Level 11] stderr| 16:05:07.873051 git.c:463 trace: built-in: git show-ref git-annex [Level 11] stderr| 16:05:07.875492 git.c:463 trace: built-in: git show-ref --hash refs/heads/git-annex [Level 11] stderr| 16:05:07.877075 git.c:463 trace: built-in: git log refs/heads/git-annex..59c9e1aeae5641af42a9132de0f1c5c1ccf6d4c0 '--pretty=%H' -n1 [Level 11] stderr| 16:05:07.879132 git.c:463 trace: built-in: git cat-file --batch [Level 11] stderr| 16:05:07.880270 git.c:463 trace: built-in: git config annex.version 10 [Level 11] stderr| 16:05:07.881469 git.c:463 trace: built-in: git config --null --list [DEBUG] Run ['git', 'cat-file', '-e', 'HEAD:.datalad/config'] (protocol_class=KillOutput) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [DEBUG] Finished ['git', 'cat-file', '-e', 'HEAD:.datalad/config'] with status 128 [DEBUG] Run ['git', 'config', '-z', '-l', '--show-origin'] (protocol_class=StdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [DEBUG] Finished ['git', 'config', '-z', '-l', '--show-origin'] with status 0 [DEBUG] Run ['git', 'cat-file', '-e', 'HEAD:.datalad/config'] (protocol_class=KillOutput) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [DEBUG] Finished ['git', 'cat-file', '-e', 'HEAD:.datalad/config'] with status 128 [DEBUG] Run ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'annex', 'initremote', 'origin', 'type=external', 'externaltype=osf', 'encryption=none', 'node=gvjbn', '-c', 'annex.dotfiles=true'] (protocol_class=StdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [DEBUG] Finished ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'annex', 'initremote', 'origin', 'type=external', 'externaltype=osf', 'encryption=none', 'node=gvjbn', '-c', 'annex.dotfiles=true'] with status 0 [DEBUG] Run ['git', 'cat-file', '-e', 'HEAD:.datalad/config'] (protocol_class=KillOutput) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [DEBUG] Finished ['git', 'cat-file', '-e', 'HEAD:.datalad/config'] with status 128 [DEBUG] Run ['git', 'config', '-z', '-l', '--show-origin'] (protocol_class=StdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [DEBUG] Finished ['git', 'config', '-z', '-l', '--show-origin'] with status 0 [DEBUG] Run ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'cat-file', 'blob', 'git-annex:remote.log'] (protocol_class=GeneratorStdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [Level 11] stderr| 16:05:08.180464 git.c:463 trace: built-in: git cat-file blob git-annex:remote.log [DEBUG] Run ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'cat-file', 'blob', 'git-annex:trust.log'] (protocol_class=GeneratorStdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [Level 11] CommandError: 'git -c diff.ignoreSubmodules=none -c core.quotepath=false cat-file blob git-annex:trust.log' failed with exitcode 128 [err: '16:05:08.182195 git.c:463 trace: built-in: git cat-file blob git-annex:trust.log | fatal: path 'trust.log' does not exist in 'git-annex''] [DEBUG] Run ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'annex', 'drop', '--force', '--key', 'XDLRA--refs', '-c', 'annex.dotfiles=true'] (protocol_class=StdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) [DEBUG] Finished ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'annex', 'drop', '--force', '--key', 'XDLRA--refs', '-c', 'annex.dotfiles=true'] with status 0 [DEBUG] Run ['git', '-c', 'diff.ignoreSubmodules=none', '-c', 'core.quotepath=false', 'annex', 'transferkey', 'XDLRA--refs', '--from=dd10930d-eb14-4c97-9e7e-be5551d23fd6', '-c', 'annex.dotfiles=true'] (protocol_class=StdOutErrCapture) (cwd=/tmp/gvjbn/.git/dl-repoannex/origin/repoannex) ```

and there it hangs. So it is an 'annex transferkey' but I do not see any size change there etc... if I make copy/rerun manually with --debug there

full log trace

```shell ❯ DATALAD_LOG_LEVEL=debug 'git' '-c' 'diff.ignoreSubmodules=none' '-c' 'core.quotepath=false' 'annex' --debug 'transferkey' 'XDLRA--refs' '--from=5cca7d1d-437b-4f2f-9d60-73e349813574' '-c' 'annex.dotfiles=true' [2024-02-13 16:13:10.881794966] (Utility.Process) process [1099420] read: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","-c","annex.dotfiles=true","show-ref","git-annex"] [2024-02-13 16:13:10.884209951] (Utility.Process) process [1099420] done ExitSuccess [2024-02-13 16:13:10.884969642] (Utility.Process) process [1099421] read: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","-c","annex.dotfiles=true","show-ref","--hash","refs/heads/git-annex"] [2024-02-13 16:13:10.887391647] (Utility.Process) process [1099421] done ExitSuccess [2024-02-13 16:13:10.888530492] (Utility.Process) process [1099422] read: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","-c","annex.dotfiles=true","log","refs/heads/git-annex..42a65c105dda79dca024be8a64521e8824ffc5b8","--pretty=%H","-n1"] [2024-02-13 16:13:10.891665292] (Utility.Process) process [1099422] done ExitSuccess [2024-02-13 16:13:10.892287012] (Annex.Branch) read remote.log [2024-02-13 16:13:10.900718114] (Utility.Process) process [1099423] chat: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","-c","annex.dotfiles=true","cat-file","--batch"] [2024-02-13 16:13:10.905447758] (Utility.Process) process [1099424] chat: /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA [] [2024-02-13 16:13:10.90555036] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] <-- GETVERSION [DEBUG] Enable posting DataLad config overrides CLI/ENV as GIT_CONFIG items in process ENV [DEBUG] Run ['git', 'version'] (protocol_class=StdOutErrCapture) (cwd=None) [DEBUG] Finished ['git', 'version'] with status 0 [DEBUG] Not retro-fitting GitRepo with deprecated symbols, datalad-deprecated package not found [DEBUG] Apply datalad-next patch to annexrepo.py:AnnexRepo.enable_remote [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Failed to import requests_ftp, thus no ftp support: ModuleNotFoundError(No module named 'requests_ftp') [DEBUG] Apply datalad-next patch to create_sibling_ghlike.py:_GitHubLike._set_request_headers [DEBUG] Apply datalad-next patch to interface.(utils|base).py:_execute_command_ [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Apply patch to datalad.core.distributed.push._transfer_data [DEBUG] Patching datalad.core.distributed.push.Push docstring and parameters [DEBUG] Building doc for [DEBUG] Patching datalad.support.AnnexRepo.get_export_records (new method) [DEBUG] Apply patch to datalad.core.distributed.push._push [DEBUG] Apply patch to datalad.distribution.siblings._enable_remote [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Replace special remote _main() with datalad-next's progress logging enabled variant [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Apply patch to datalad.distributed.create_sibling_gitlab._proc_dataset [DEBUG] Stop advertising discontinued "hierarchy" layout for `create_siblign_gitlab()` [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Building doc for [DEBUG] Apply patch to datalad.core.local.run.format_command [DEBUG] Apply patch to datalad.distribution.update._choose_update_target [2024-02-13 16:13:11.050201466] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] --> VERSION 1 [2024-02-13 16:13:11.050286775] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] <-- CANVERIFY [2024-02-13 16:13:11.050565926] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] --> CANVERIFY-YES [2024-02-13 16:13:11.050608601] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] <-- ISSTABLE [2024-02-13 16:13:11.050800033] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] --> ISSTABLE-NO [2024-02-13 16:13:11.050842405] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] <-- ISCRYPTOGRAPHICALLYSECURE [2024-02-13 16:13:11.050987764] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-backend-XDLRA[1] --> ISCRYPTOGRAPHICALLYSECURE-NO [2024-02-13 16:13:11.052128431] (Utility.Process) process [1099434] chat: /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf [] [2024-02-13 16:13:11.125947184] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] --> VERSION 1 [2024-02-13 16:13:11.126039146] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] <-- EXTENSIONS INFO GETGITREMOTENAME ASYNC [2024-02-13 16:13:11.126243833] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] --> EXTENSIONS [2024-02-13 16:13:11.126287875] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] <-- PREPARE [2024-02-13 16:13:11.126538659] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] --> GETCONFIG node [2024-02-13 16:13:11.126580498] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] <-- VALUE gvjbn [DEBUG] Run ['git', 'version'] (protocol_class=StdOutErrCapture) (cwd=None) [DEBUG] Finished ['git', 'version'] with status 0 [DEBUG] Not retro-fitting GitRepo with deprecated symbols, datalad-deprecated package not found [DEBUG] Importing keyring [2024-02-13 16:13:13.562265998] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] --> PREPARE-SUCCESS [2024-02-13 16:13:13.562455525] (Annex.ExternalAddonProcess) /home/yoh/proj/datalad/datalad-osf/venvs/dev3.11/bin/git-annex-remote-osf[1] <-- TRANSFER RETRIEVE XDLRA--refs ./annex/tmp/XDLRA--refs ```

so seems stalling at that git-annex-remote-osf TRANSFER request silently. and again size of folder doesn't grow.

[mih]

I can reproduce the issue for the given repo (tried only git-clone). I can also confirm that the repo content key is present and contains a valid repo (downloaded manually to check). I can also confirm that the XDLRA--refs key points to the matching HEADs of a master and a git-annex branch.

Bottom line: server-side things look normal.

Looking at the clone, and its .git/dl-repoannex/origin, I only see an empty mirrorrepo, and not the one present in the OSF project. I suspect that some detection result indicates that there is no repo deposit.

Rerunning things with full debug: DATALAD_LOG_LEVEL=1 git clone -v osf://gvjbn osf2

Observation of "odd" things (may or may not be useful clues):

Level 11] CommandError: 'git -c diff.ignoreSubmodules=none -c core.quotepath=false cat-file blob git-annex:trust.log' failed with exitcode 128 [err: 'fatal: path 'trust.log' does not exist in 'git-annex''] 
[Level 8] CommandError: 'git -c diff.ignoreSubmodules=none -c core.quotepath=false cat-file blob git-annex:trust.log' failed with exitcode 128 [err: 'fatal: path 'trust.log' does not exist in 'git-annex''] [annexrepo.py:get_special_remotes:867,gitrepo.py:call_git_items_:525,gitrepo.py:_generator_call_git:363,<frozen _collections_abc>:__next__:330,nonasyncrunner.py:send:100,nonasyncrunner.py:_locked_send:125,nonasyncrunner.py:_check_result:96,nonasyncrunner.py:_check_result:298] 

XDLRA--refs download failed

[Level 8] CommandError: 'git -c diff.ignoreSubmodules=none -c core.quotepath=false annex transferkey XDLRA--refs --from=d4d04d9d-d34d-42ee-8d10-15b6056b616f --debug -c annex.dotfiles=true' failed with exitcode 1 under /tmp/osf2/.git/dl-repoannex/origin/repoannex [err: '[2024-02-14 09:22:29.019326476] (Utility.Process) process [166029] read: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","-c","annex.dotfiles=true","show-ref","git-annex"]

[Level 5] Credentials lookup attempt via env var DATALAD_https://osf.io_token 
[2024-02-14 09:22:30.269378618] (Annex.ExternalAddonProcess) /home/mih/env/datalad-dev/bin/git-annex-remote-osf[2] --> PREPARE-FAILURE Failed to obtain OSF node handle: 
[2024-02-14 09:22:30.276188075] (Utility.Process) process [166096] chat: /home/mih/env/datalad-dev/bin/git-annex-backend-XDLRA []

Will continue investigating...

[adswa]

Looks like this is dependent on the sibling mode. "human-readable" exports seemingly work fine...

[mih]

I improved the error messaging in datalad-osf. Now the log says:

❯ git clone -v osf://gvjbn osf8
Cloning into 'osf8'...
[DATALAD-ANNEX] Connecting git-upload-pack

[DATALAD-ANNEX] Get refs from remote
[DATALAD-ANNEX] Remote appears to have no refs
[DATALAD-ANNEX] CommandError: 'git -c diff.ignoreSubmodules=none -c core.quotepath=false annex transferkey XDLRA--refs --from=8932738f-854b-4182-afac-b14ffd9ca685 -c annex.dotfiles=true' failed with exitcode 1 under /tmp/osf8/.git/dl-repoannex/origin/repoannex [err: 'Failed to obtain OSF node handle ('gvjbn'): UnauthorizedException() [using credentials {'token': 'rhHlsQ...', 'username': None, 'password': None}]']
[DATALAD-ANNEX] Established mirror
warning: You appear to have cloned an empty repository.

It fails on a fundamental access authorization level. This is confusing.

The osf special remote runs code that retrieves a token that was stored in my credential store, using the credential support in datalad-core. It was invisible to the credential tooling in datalad-next, because there is no legacy "provider" configuration (without which it cannot know what to look for).

With that token, the following line in try-except fails with UnauthorizedException:

        # next one just sets up the stage, no requests performed yet, hence
        # no error checking needed
        # supply both auth credentials, so osfclient can fall back on user/pass
        # if needed
        osf = OSF(**creds)
        # next one performs initial auth
        try:
            self.node = osf.project(node_id)
        except Exception as e:
            # we need to raise RemoteError() such that PREPARE-FAILURE
            # is reported, sadly that doesn't give users any clue
            # TODO support datalad logging here
            raise RemoteError(
                f'Failed to obtain OSF node handle ({node_id!r}): {e!r} [using credentials {creds!r}]'
            )

Will look into not passing any credential now...

And it seems not having or not passing credentials now let's me replicate the "hangs forever" observation.

Update: It is not "forever", it is merely very slow. It seems that when not passing credentials, each request literally takes minutes (and more than one request needs to be made). However, the requests eventually succeed!

If this assessment is correct, I'd speculate that this is an OSF "bug". They reject credentials due to a mismatch with a target project, even though no credential/authorization is needed. The workaround via no authentication is then soured by a service-side penalty for unauthenticated access.

If this is a correct assessment, there is little we can do implementation-wise. If we try unauthenticated access first, in order to enable "public access", we introduce a 10-20min latency for any "personal use" -- unacceptable. The best thing we can do is to document this behavior, and to make it clearer in the logs what is happening, and how to bypass credentials submissing to make things work at all -- even if only at a ridiculous speed.

Here is how it looks when not passing a credential:

❯ git clone -v osf://gvjbn osf9
Cloning into 'osf9'...
[DATALAD-ANNEX] Connecting git-upload-pack

[DATALAD-ANNEX] Get refs from remote
[DATALAD-ANNEX] Set mirror to remote state
[DATALAD-ANNEX] (recording state in git...)

[DATALAD-ANNEX] get XDLRA--repo-export (from origin...) 
ok

[DATALAD-ANNEX] Extracting repository archive
[DATALAD-ANNEX] Established mirror
remote: Enumerating objects: 52257, done.
remote: Total 52257 (delta 0), reused 0 (delta 0), pack-reused 52257
Receiving objects: 100% (52257/52257), 4.43 MiB | 42.38 MiB/s, done.
Resolving deltas: 100% (6575/6575), done.
git clone -v osf://gvjbn osf9  8.67s user 3.30s system 0% cpu 20:33.28 total
❯ ls osf9
 20.2.0   20.2.2   20.2.4   21.0.4   23.0.0
 20.2.1   20.2.3   20.2.5   22.1.1   corrupted-template_MNI152NLin2009cAsym_res-01_T1w.tar.gz

(as shown in the log, this took 20min)

[mih]

Looks like this is dependent on the sibling mode. "human-readable" exports seemingly work fine...

@adswa can you confirm (or not) that all "human-readable" projects you tested are "your's", and that you have a token present in your setup?

If so, my assessment would hold. If not, something would still be missing.

[adswa]

yes, indeed - all my own projects, and with a token setup