git annex get is silently stuck on P2P

Please describe the problem.

Trying to get fresh data from a server but annex get is just stuck without any output. Here is how it looks with --debug:

yoh@typhon:/mnt/DATA/data/yoh/1076_spacetop$ git annex get --debug sub-0002/ses-01/dwi/sub-0002_ses-01_acq-96dirX6b0Xmb_dwi.nii.gz
[2024-05-29 14:08:30.203689795] (Utility.Process) process [3922981] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.debug=true","ls-files","--stage","-z","--error-unmatch","--","sub-0002/ses-01/dwi/sub-0002_ses-01_acq-96dirX6b0Xmb_dwi.nii.gz"]
[2024-05-29 14:08:30.204159722] (Utility.Process) process [3922982] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.debug=true","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)","--buffer"]
[2024-05-29 14:08:30.204574378] (Utility.Process) process [3922983] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.debug=true","cat-file","--batch=%(objectname) %(objecttype) %(objectsize)","--buffer"]
[2024-05-29 14:08:30.205075804] (Utility.Process) process [3922984] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.debug=true","show-ref","git-annex"]
[2024-05-29 14:08:30.207328301] (Utility.Process) process [3922984] done ExitSuccess
[2024-05-29 14:08:30.207536385] (Utility.Process) process [3922985] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.debug=true","show-ref","--hash","refs/heads/git-annex"]
[2024-05-29 14:08:30.209355606] (Utility.Process) process [3922985] done ExitSuccess
[2024-05-29 14:08:30.209800913] (Utility.Process) process [3922986] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.debug=true","cat-file","--batch=%(objectname) %(objecttype) %(objectsize)","--buffer"]
get sub-0002/ses-01/dwi/sub-0002_ses-01_acq-96dirX6b0Xmb_dwi.nii.gz [2024-05-29 14:08:30.215082484] (Utility.Process) process [3922987] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.debug=true","cat-file","--batch"]
(from origin...) 
[2024-05-29 14:08:30.225575902] (Utility.Process) process [3922988] read: ssh ["-O","stop","-S","bids@rolando.cns.dartmouth.edu","-o","ControlMaster=auto","-o","ControlPersist=yes","localhost"] in ".git/annex/ssh/"
[2024-05-29 14:08:30.230512383] (Utility.Process) process [3922988] done ExitSuccess
[2024-05-29 14:08:30.231078838] (Utility.Process) process [3922989] read: ssh ["-o","BatchMode=true","-S",".git/annex/ssh/bids@rolando.cns.dartmouth.edu","-o","ControlMaster=auto","-o","ControlPersist=yes","-n","-T","bids@rolando.cns.dartmouth.edu","true"]
[2024-05-29 14:08:31.042361711] (Utility.Process) process [3922989] done ExitSuccess
[2024-05-29 14:08:31.043219566] (Utility.Process) process [3923085] chat: ssh ["bids@rolando.cns.dartmouth.edu","-S",".git/annex/ssh/bids@rolando.cns.dartmouth.edu","-o","ControlMaster=auto","-o","ControlPersist=yes","-T","git-annex-shell 'p2pstdio' '/inbox/BIDS/Wager/Wager/1076_spacetop' '--debug' '97b6f5e4-4642-43a7-988a-c483caf553c5' --uuid 590b4fd0-0142-4e9d-8964-d1158c242c6a"]
[2024-05-29 14:08:31.540468659] (P2P.IO) [ThreadId 4] P2P > AUTH-SUCCESS 590b4fd0-0142-4e9d-8964-d1158c242c6a
[2024-05-29 14:08:31.539643152] (P2P.IO) [ssh connection Just 3923085] [ThreadId 4] P2P < AUTH-SUCCESS 590b4fd0-0142-4e9d-8964-d1158c242c6a
[2024-05-29 14:08:31.539846045] (P2P.IO) [ssh connection Just 3923085] [ThreadId 4] P2P > VERSION 1
[2024-05-29 14:08:31.542774097] (P2P.IO) [ThreadId 4] P2P < VERSION 1
[2024-05-29 14:08:31.543007073] (P2P.IO) [ThreadId 4] P2P > VERSION 1
[2024-05-29 14:08:31.541288127] (P2P.IO) [ssh connection Just 3923085] [ThreadId 4] P2P < VERSION 1
[2024-05-29 14:08:31.541362199] (P2P.IO) [ssh connection Just 3923085] [ThreadId 4] P2P > GET 0 sub-0002/ses-01/dwi/sub-0002_ses-01_acq-96dirX6b0Xmb_dwi.nii.gz MD5E-s239384952--c3aaaebbed3ef5932b4390ddb47d2150.nii.gz
[2024-05-29 14:08:31.544298446] (P2P.IO) [ThreadId 4] P2P < GET 0 sub-0002/ses-01/dwi/sub-0002_ses-01_acq-96dirX6b0Xmb_dwi.nii.gz MD5E-s239384952--c3aaaebbed3ef5932b4390ddb47d2150.nii.gz

and on the server it looks like ( I killed one, client reinitiated, this is current one)

bids     27577  0.3  0.0 1074226428 11120 ?    Ssl  14:10   0:00 /data/home/bids/git-annexes/10.20231129+git83-g86dbe9a825/usr/lib/git-annex.linux/exe/git-annex-shell --library-path /data/home/bids/git-annexes/10.20231129+git83-g86dbe9a825/usr/lib/git-annex.linux//lib/x86_64-linux-gnu: /data/home/bids/git-annexes/10.20231129+git83-g86dbe9a825/usr/lib/git-annex.linux/shimmed/git-annex-shell/git-annex-shell p2pstdio /inbox/BIDS/Wager/Wager/1076_spacetop.git --debug 97b6f5e4-4642-43a7-988a-c483caf553c5 --uuid 40795e62-527c-4d26-ae8c-af42a6e2da5a

and on server config is

[annex]
        sshcaching = false
        autoupgraderepository = false
        pidlock = true

[safe]
        directory = /inbox/BIDS

and that directory /inbox/BIDS is NFS mounted.

Not sure what nobs to turn to help diagnose the issue.

The git-annex on client side is 10.20240129-1~ndall+1

What steps will reproduce the problem?

What version of git-annex are you using? On what operating system?

Please provide any additional information below.

# If you can, paste a complete transcript of the problem occurring here.
# If the problem is with the git-annex assistant, paste in .git/annex/daemon.log


# End of transcript or log.

Have you had any luck using git-annex before? (Sometimes we get tired of reading bug reports all day and a lil' positive end note does wonders)

RSS Atom

odd odd odd

and I cannot copy from the server to the client:

[bids@rolando 1076_spacetop.git] > git annex copy --debug --to typhon --fast --not --in typhon
yoh@typhon.dartmouth.edu's password: 
[2024-05-29 14:21:40.601369476] (Utility.Process) process [28828] read: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","ls-tree","--full-tree","-z","-r","--","refs/heads/git-annex"]
[2024-05-29 14:21:40.602439011] (Utility.Process) process [28829] chat: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","cat-file","--batch=%(objectname) %(objecttype) %(objectsize)","--buffer"]
[2024-05-29 14:21:40.775458494] (Messages.explain) [ MD5E-s292602526--2069b86f10e1a39bda5a6ed8996078d4.nii.gz does not match:not in=typhon[TRUE] ]

[2024-05-29 14:21:40.793913739] (Messages.explain) [ MD5E-s2615170--589b64f4cd3067f468408d809c7f1037.nii.gz does not match:not in=typhon[TRUE] ]

[2024-05-29 14:21:40.811856562] (Messages.explain) [ MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz matches:not in=typhon[FALSE] ]

copy MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz (to typhon...) [2024-05-29 14:21:40.974993044] (Utility.Process) process [28817] done ExitSuccess
[2024-05-29 14:21:40.975527841] (Utility.Process) process [28816] done ExitSuccess


  You have enabled concurrency, but git-annex is not able to use ssh connection caching. This may result in multiple ssh processes prompting for passwords at the same time.

  annex.sshcaching is not set to true
[2024-05-29 14:21:40.977267402] (Utility.Process) process [28831] chat: ssh ["yoh@typhon.dartmouth.edu","-T","git-annex-shell 'p2pstdio' '/mnt/DATA/data/yoh/1076_spacetop' '--debug' '40795e62-527c-4d26-ae8c-af42a6e2da5a' --uuid 97b6f5e4-4642-43a7-988a-c483caf553c5"]
yoh@typhon.dartmouth.edu's password: 
[2024-05-29 14:21:57.87732028] (P2P.IO) [ThreadId 4] P2P > AUTH-SUCCESS 97b6f5e4-4642-43a7-988a-c483caf553c5
[2024-05-29 14:21:57.879974047] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P < AUTH-SUCCESS 97b6f5e4-4642-43a7-988a-c483caf553c5
[2024-05-29 14:21:57.880228709] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P > VERSION 1
[2024-05-29 14:21:57.878927215] (P2P.IO) [ThreadId 4] P2P < VERSION 1
[2024-05-29 14:21:57.878991142] (P2P.IO) [ThreadId 4] P2P > VERSION 1
[2024-05-29 14:21:57.881305277] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P < VERSION 1
[2024-05-29 14:21:57.881487685] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P > PUT  MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz
[2024-05-29 14:21:57.880214299] (P2P.IO) [ThreadId 4] P2P < PUT  MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz
[2024-05-29 14:21:57.880467298] (P2P.IO) [ThreadId 4] P2P > PUT-FROM 0
[2024-05-29 14:21:57.882841829] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P < PUT-FROM 0

NB we had issue with a recent 10GB switch update which was worked around by me reducing MTU on my servers from Jumbo frames to regular 1500 . But it manifested that scp did not work. Here scp worked (I did scp on typhon from rolando). And for heejung it does not work to pull data from roland to discovery.

Comment by yarikoptic — Wed May 29 18:25:11 2024

Remove comment

odd odd odd

and I cannot copy from the server to the client:

[bids@rolando 1076_spacetop.git] > git annex copy --debug --to typhon --fast --not --in typhon
yoh@typhon.dartmouth.edu's password: 
[2024-05-29 14:21:40.601369476] (Utility.Process) process [28828] read: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","ls-tree","--full-tree","-z","-r","--","refs/heads/git-annex"]
[2024-05-29 14:21:40.602439011] (Utility.Process) process [28829] chat: git ["--git-dir=.","--literal-pathspecs","-c","annex.debug=true","cat-file","--batch=%(objectname) %(objecttype) %(objectsize)","--buffer"]
[2024-05-29 14:21:40.775458494] (Messages.explain) [ MD5E-s292602526--2069b86f10e1a39bda5a6ed8996078d4.nii.gz does not match:not in=typhon[TRUE] ]

[2024-05-29 14:21:40.793913739] (Messages.explain) [ MD5E-s2615170--589b64f4cd3067f468408d809c7f1037.nii.gz does not match:not in=typhon[TRUE] ]

[2024-05-29 14:21:40.811856562] (Messages.explain) [ MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz matches:not in=typhon[FALSE] ]

copy MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz (to typhon...) [2024-05-29 14:21:40.974993044] (Utility.Process) process [28817] done ExitSuccess
[2024-05-29 14:21:40.975527841] (Utility.Process) process [28816] done ExitSuccess


  You have enabled concurrency, but git-annex is not able to use ssh connection caching. This may result in multiple ssh processes prompting for passwords at the same time.

  annex.sshcaching is not set to true
[2024-05-29 14:21:40.977267402] (Utility.Process) process [28831] chat: ssh ["yoh@typhon.dartmouth.edu","-T","git-annex-shell 'p2pstdio' '/mnt/DATA/data/yoh/1076_spacetop' '--debug' '40795e62-527c-4d26-ae8c-af42a6e2da5a' --uuid 97b6f5e4-4642-43a7-988a-c483caf553c5"]
yoh@typhon.dartmouth.edu's password: 
[2024-05-29 14:21:57.87732028] (P2P.IO) [ThreadId 4] P2P > AUTH-SUCCESS 97b6f5e4-4642-43a7-988a-c483caf553c5
[2024-05-29 14:21:57.879974047] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P < AUTH-SUCCESS 97b6f5e4-4642-43a7-988a-c483caf553c5
[2024-05-29 14:21:57.880228709] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P > VERSION 1
[2024-05-29 14:21:57.878927215] (P2P.IO) [ThreadId 4] P2P < VERSION 1
[2024-05-29 14:21:57.878991142] (P2P.IO) [ThreadId 4] P2P > VERSION 1
[2024-05-29 14:21:57.881305277] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P < VERSION 1
[2024-05-29 14:21:57.881487685] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P > PUT  MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz
[2024-05-29 14:21:57.880214299] (P2P.IO) [ThreadId 4] P2P < PUT  MD5E-s597779--1108c4d91a2386573c50c251a0e967c2.tgz
[2024-05-29 14:21:57.880467298] (P2P.IO) [ThreadId 4] P2P > PUT-FROM 0
[2024-05-29 14:21:57.882841829] (P2P.IO) [ssh connection Just 28831] [ThreadId 4] P2P < PUT-FROM 0

Comment by yarikoptic — Wed May 29 18:25:23 2024

Remove comment

comment 3

might be (part of) mystery resolved -- dmesg on server shows bunch of

[Wed May 29 14:12:32 2024] lockd: server dbic-mrinbox not responding, still trying
[Wed May 29 14:12:32 2024] lockd: server dbic-mrinbox not responding, still trying
[Wed May 29 14:21:33 2024] lockd: server dbic-mrinbox not responding, still trying
[Wed May 29 14:23:34 2024] lockd: server dbic-mrinbox not responding, still trying
[Wed May 29 14:26:34 2024] lockd: server dbic-mrinbox not responding, still trying

although I can still read content just fine, so it is more specifically about locking I guess (despite using pidlock?)?

Comment by yarikoptic — Wed May 29 18:31:16 2024

Remove comment

Add a comment