Please describe the problem.
In recent version of git-annex (including the most recent standalone version), uploading to box is slow. Typically, it will take 25 seconds or so for git-annex to begin the upload, whereas with previous versions it happened almost instantly.
I used git bisect and rebuilds via stack to locate the commit that introduced this problem. This was the result:
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[cf51f40f0eaed2c5968f35b94bebab4a1c819491] webdav: Changed path used on webdav server for temporary files.
Please note: this is distinct from the bug I reported here (https://git-annex.branchable.com/bugs/git-annex_can_no_longer_copy_files_to_box/), since it also affects the standalone version.
What steps will reproduce the problem?
Use a version of git annex built after the commit above from Sept. 15 (e.g., a recent standalone):
Use a repo with a box remote set up with encryption and chunking:
WEBDAV_USERNAME=[username] WEBDAV_PASSWORD=[passwd] git annex initremote box type=webdav url=https://dav.box.com/dav/mystuff/annex chunk=100mb keyid=[keyid]
echo "Hello, world!" > test.txt
git add test.txt
git annex --verbose --debug copy -t box test.txt
What version of git-annex are you using? On what operating system?
Tested with the nightly standalone build on arch linux:
git-annex version: 6.20171006-gbeca3ce2b
build flags: Assistant Webapp Pairing Testsuite S3(multipartupload)(storageclasses) WebDAV Inotify DBus DesktopNotify ConcurrentOutput TorrentParser MagicMime Feeds Quvi
dependency versions: aws-0.14.1 bloomfilter-2.0.1.0 cryptonite-0.20 DAV-1.3.1 feed-0.3.11.1 ghc-8.0.1 http-client-0.4.31.1 persistent-sqlite-2.6 torrent-10000.0.0 uuid-1.3.12 yesod-1.4.3
key/value backends: SHA256E SHA256 SHA512E SHA512 SHA224E SHA224 SHA384E SHA384 SHA3_256E SHA3_256 SHA3_512E SHA3_512 SHA3_224E SHA3_224 SHA3_384E SHA3_384 SKEIN256E SKEIN256 SKEIN512E SKEIN512 SHA1E SHA1 MD5E MD5 WORM URL
remote types: git gcrypt p2p S3 bup directory rsync web bittorrent webdav tahoe glacier ddar hook external
Please provide any additional information below.
Here is the output:
% ~/git-annex.linux/git-annex --verbose --debug copy -t box test.txt
[2017-10-07 10:13:25.283802979] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","git-annex"]
[2017-10-07 10:13:25.294784901] process done ExitSuccess
[2017-10-07 10:13:25.295173712] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","--hash","refs/heads/git-annex"]
[2017-10-07 10:13:25.305375915] process done ExitSuccess
[2017-10-07 10:13:25.306659057] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch"]
[2017-10-07 10:13:25.307617362] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"]
[2017-10-07 10:13:25.338084356] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","ls-files","--cached","-z","--","test.txt"]
copy test.txt [2017-10-07 10:13:25.360741244] chat: gpg ["--quiet","--trust-model","always","--decrypt"]
[2017-10-07 10:13:25.454260122] process done ExitSuccess
(checking box...) (to box...)
[2017-10-07 10:13:26.215000484] chat: gpg ["--quiet","--trust-model","always","--batch","--passphrase-fd","18","--symmetric","--force-mdc","--no-textmode"]
100% 2 B/s 7s[2017-10-07 10:13:58.059203157] process done ExitSuccess
ok
Note the 32 second delay from 10:13:26 to 10:13:58 here
[2017-10-07 10:13:58.066819166] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","hash-object","-w","--stdin-paths","--no-filters"]
[2017-10-07 10:13:58.067584497] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","update-index","-z","--index-info"]
[2017-10-07 10:13:58.216568109] process done ExitSuccess
[2017-10-07 10:13:58.216839725] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","--hash","refs/heads/git-annex"]
[2017-10-07 10:13:58.227738805] process done ExitSuccess
(recording state in git...)
[2017-10-07 10:13:58.227942884] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","write-tree"]
[2017-10-07 10:13:58.386915393] process done ExitSuccess
[2017-10-07 10:13:58.387325088] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","commit-tree","bf90d33cdcf43119d2608e90fa6fdc23c497950d","--no-gpg-sign","-p","refs/heads/git-annex"]
[2017-10-07 10:13:58.400174021] process done ExitSuccess
[2017-10-07 10:13:58.400315661] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","update-ref","refs/heads/git-annex","b9583c0cf24933de01063281108f6d0c3a98053b"]
[2017-10-07 10:13:58.413220259] process done ExitSuccess
[2017-10-07 10:13:58.414476091] process done ExitSuccess
[2017-10-07 10:13:58.414890325] process done ExitSuccess
[2017-10-07 10:13:58.415545095] process done ExitSuccess
Compare this with the results of git-annex built with stack that does not include the problematic commit:
git-annex version: 6.20170915-g122396029
build flags: Assistant Webapp Pairing Testsuite S3(multipartupload)(storageclasses) WebDAV Inotify ConcurrentOutput TorrentParser Feeds Quvi
dependency versions: aws-0.16 bloomfilter-2.0.1.0 cryptonite-0.21 DAV-1.3.1 feed-0.3.12.0 ghc-8.0.2 http-client-0.5.6.1 persistent-sqlite-2.6.2 torrent-10000.1.1 uuid-1.3.13 yesod-1.4.5
key/value backends: SHA256E SHA256 SHA512E SHA512 SHA224E SHA224 SHA384E SHA384 SHA3_256E SHA3_256 SHA3_512E SHA3_512 SHA3_224E SHA3_224 SHA3_384E SHA3_384 SKEIN256E SKEIN256 SKEIN512E SKEIN512 SHA1E SHA1 MD5E MD5 WORM URL
remote types: git gcrypt p2p S3 bup directory rsync web bittorrent webdav tahoe glacier ddar hook external
local repository version: 5
supported repository versions: 3 5 6
upgrade supported from repository versions: 0 1 2 3 4 5
operating system: linux x86_64
Here is the output:
% git annex --verbose --debug copy -t box test.txt
[2017-10-07 10:51:28.863004037] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","git-annex"]
[2017-10-07 10:51:28.866087687] process done ExitSuccess
[2017-10-07 10:51:28.866184907] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","--hash","refs/heads/git-annex"]
[2017-10-07 10:51:28.868674623] process done ExitSuccess
[2017-10-07 10:51:28.869107711] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","log","refs/heads/git-annex..5cc79198b2eb9e281d64b9eed7b1b6a2e869fb20","--pretty=%H","-n1"]
[2017-10-07 10:51:28.87271685] process done ExitSuccess
[2017-10-07 10:51:28.873655522] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch"]
[2017-10-07 10:51:28.874173468] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"]
[2017-10-07 10:51:28.896038454] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","ls-files","--cached","-z","--","test.txt"]
copy test.txt [2017-10-07 10:51:28.909441282] chat: gpg ["--quiet","--trust-model","always","--decrypt"]
[2017-10-07 10:51:28.997627719] process done ExitSuccess
(checking box...) (to box...)
[2017-10-07 10:51:29.838627434] chat: gpg ["--quiet","--trust-model","always","--batch","--passphrase-fd","18","--symmetric","--force-mdc","--no-textmode"]
100% 85 B/s 0s[2017-10-07 10:51:34.465610054] process done ExitSuccess
ok
Notice the 5 second gap here:
[2017-10-07 10:51:34.469743494] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","hash-object","-w","--stdin-paths","--no-filters"]
[2017-10-07 10:51:34.47009347] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","update-index","-z","--index-info"]
[2017-10-07 10:51:34.588535947] process done ExitSuccess
[2017-10-07 10:51:34.588699027] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","--hash","refs/heads/git-annex"]
[2017-10-07 10:51:34.591436472] process done ExitSuccess
(recording state in git...)
[2017-10-07 10:51:34.59158293] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","write-tree"]
[2017-10-07 10:51:34.767927859] process done ExitSuccess
[2017-10-07 10:51:34.768081231] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","commit-tree","b7c89dee187ca46d21ad05937d746acb149c323e","--no-gpg-sign","-p","refs/heads/git-annex"]
[2017-10-07 10:51:34.799274341] process done ExitSuccess
[2017-10-07 10:51:34.799458862] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","update-ref","refs/heads/git-annex","676897d54eeecff41c28432e903671400b3c0b84"]
[2017-10-07 10:51:34.802489572] process done ExitSuccess
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)
Yes! Thank you!
I suspect that the problem dealt with in 2ca1d3cc0134134314649c21822bf1352df52e93 is responsible for this behavior. If many redirects are followed before git-annex gives up, it would explain why it's taking so long.
In redirecting from a non-existant file to some index.php file that itself doesn't exist, and so on forever, box.com is clearly a horrible, broken, very bad webdav server. Given that it's so broken, it's not terribly surprising that small changes might expose that or another brokenness in different ways. Changing the location of a temp file from a tmp subdirectory to the parent directory is not the kind of thing that causes 30 second delays with non-broken servers.
I have not been able to reproduce the problem here though so that is just a theory.
I am not inclined to make random changes to try to work around random breakage in box.com. That is a game you lose before you start playing.
It may be that deleting line 132 from Remote/WebDAV.hs avoids the problem.
Since the parent directory of the temp file is the top of the webdav repository, and so already exists, that line is now unnecessary. Since you can reproduce the problem and build from source, can you test that change?
Also, I've added logging of all webdav operations with --debug, which should help with determining what operation is being slow.
I'm sorry to hear that Box has a buggy WebDav server. I would gladly shift away from Box except that I have unlimited storage through my university. So thanks for being willing to help debug this problem!
Here is the first test without making the change above but with the new debug information. You can see the big gap after 9:04:54 and "getProps .". This test actually failed, so it could be that this bug is related to the earlier one I reported. I cannot reproduce this reliably with the latest build using stack. Sometimes git annex uploads the file after a long delay, sometimes it fails.
git-annex-version
I removed line 134 and rebuilt using Stack:
The file uploaded right away: