Upload to box very slow

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!

fixed --Joey

RSS Atom

comment 1

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.

    maybe noop (void . mkColRecursive) (locationParent tmp)

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?

Comment by joey — Sat Oct 7 17:03:56 2017

Remove comment

comment 2

Also, I've added logging of all webdav operations with --debug, which should help with determining what operation is being slow.

Comment by joey — Sat Oct 7 18:05:44 2017

Remove comment

First test

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 --verbose --debug copy -t box test.txt
 [2017-10-09 09:04:52.566913246] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","git-annex"]
 [2017-10-09 09:04:52.570241399] process done ExitSuccess
 [2017-10-09 09:04:52.570335828] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","--hash","refs/heads/git-annex"]
 [2017-10-09 09:04:52.573016175] process done ExitSuccess
 [2017-10-09 09:04:52.57406831] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch"]
 [2017-10-09 09:04:52.57444107] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"]
 [2017-10-09 09:04:52.595364899] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","ls-files","--cached","-z","--","test.txt"]
 copy test.txt [2017-10-09 09:04:52.609509008] chat: gpg ["--quiet","--trust-model","always","--decrypt"]
 [2017-10-09 09:04:52.699246422] process done ExitSuccess
 (checking box...) [2017-10-09 09:04:52.739720313] getProps 90a/d4d/GPGHMACSHA1--53636e5e7a50bc58eae478ddc260bb5abd899d03/GPGHMACSHA1--53636e5e7a50bc58eae478ddc260bb5abd899d03
 (to box...)
 [2017-10-09 09:04:54.134452518] chat: gpg ["--quiet","--trust-model","always","--batch","--passphrase-fd","19","--symmetric","--force-mdc","--no-textmode"]
 [2017-10-09 09:04:54.188323123] getProps .
 [2017-10-09 09:05:24.214747951] mkCol .
 [2017-10-09 09:05:24.900782145] process done ExitSuccess

   DAV failure: Status {statusCode = 405, statusMessage = "Method Not Allowed"} "<?xml version=\"1.0\" encoding=\"utf-8\"?>\n<d:error xmlns:d=\"DAV:\" xmlns:s=\"http://sabredav.org/ns\">\n  <s:exception>Sabre_DAV_Exception_MethodNotAllowed</s:exception>\n  <s:message>The resource you tried to create already exists</s:message>\n</d:error>\n" HTTP request: "MKCOL" "/dav/mystuff/annex/."
   failed
 [2017-10-09 09:05:24.903485338] process done ExitSuccess
 [2017-10-09 09:05:24.904346521] process done ExitSuccess
 git-annex: copy: 1 failed

git-annex-version

   git-annex version: 6.20171007-g7613a5e81                                                                                                                      
   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

Comment by madalu — Mon Oct 9 14:22:22 2017

Remove comment

Second test (without line 134)

I removed line 134 and rebuilt using Stack:

   maybe noop (void . mkColRecursive) (locationParent tmp)

The file uploaded right away:

 % git annex --verbose --debug copy -t box test.txt                                                                                                
 [2017-10-09 09:36:32.711847016] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","git-annex"]                                     
 [2017-10-09 09:36:32.809619031] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:32.809888889] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","--hash","refs/heads/git-annex"]                 
 [2017-10-09 09:36:32.812814521] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:32.829791929] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch"]                                       
 [2017-10-09 09:36:32.830463363] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"]
 [2017-10-09 09:36:32.862446411] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","ls-files","--cached","-z","--","test.txt"]                 
 copy test.txt [2017-10-09 09:36:32.904592591] chat: gpg ["--quiet","--trust-model","always","--decrypt"]                                                      
 [2017-10-09 09:36:33.015053401] process done ExitSuccess                                                                                                      
 (checking box...) [2017-10-09 09:36:33.127413417] getProps 90a/d4d/GPGHMACSHA1--53636e5e7a50bc58eae478ddc260bb5abd899d03/GPGHMACSHA1--53636e5e7a50bc58eae478ddc260bb5abd899d03
 (to box...)                                                                                                                                                   
 [2017-10-09 09:36:35.646456289] chat: gpg ["--quiet","--trust-model","always","--batch","--passphrase-fd","19","--symmetric","--force-mdc","--no-textmode"]   
 [2017-10-09 09:36:35.700070757] putContent git-annex-webdav-tmp-GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624                                         
 100%              153 B/s 0s[2017-10-09 09:36:37.830031092] delContent 18f/335/GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624/GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624
 [2017-10-09 09:36:38.453637089] getProps 18f/335/GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624                                                        
 [2017-10-09 09:36:38.891805895] mkCol 18f/335/GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624                                                           
 [2017-10-09 09:36:39.47474337] moveContent git-annex-webdav-tmp-GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624 https://dav.box.com/dav/mystuff/annex/18f/335/GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624/GPGHMACSHA1--b7d5df88040626033a471159a0652c9e3777d624
 [2017-10-09 09:36:40.325543883] process done ExitSuccess                                                                                                      
 ok                                                                                                                                                            
 [2017-10-09 09:36:40.343371234] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","hash-object","-w","--stdin-paths","--no-filters"]          
 [2017-10-09 09:36:40.346018836] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","update-index","-z","--index-info"]                         
 [2017-10-09 09:36:40.574634504] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:40.574833127] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","show-ref","--hash","refs/heads/git-annex"]                 
 [2017-10-09 09:36:40.579083747] process done ExitSuccess                                                                                                      
 (recording state in git...)                                                                                                                                   
 [2017-10-09 09:36:40.579508229] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","write-tree"]                                               
 [2017-10-09 09:36:40.908596805] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:40.908746261] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","commit-tree","890c8c30542bfb566cb0f6c18948661f9dba3477","--no-gpg-sign","-p","refs/heads/git-annex"]
 [2017-10-09 09:36:40.911636345] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:40.911746341] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","update-ref","refs/heads/git-annex","8f02270fa945f2381b63ed2f8280f8f966628a70"]
 [2017-10-09 09:36:40.916033767] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:40.917348489] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:40.917759841] process done ExitSuccess                                                                                                      
 [2017-10-09 09:36:40.918326516] process done ExitSuccess

Comment by madalu — Mon Oct 9 14:40:45 2017

Remove comment

Add a comment