This commit is contained in:
wolf480@8ad1ccdd08efc303a88f7e88c4e629be6637a44e 2023-03-26 18:39:20 +00:00 committed by admin
parent 4d198a6665
commit 140edd65ac

View file

@ -0,0 +1,87 @@
### Please describe the problem.
When getting a lot of objects from an external special remote of the exporttree kind,
sometimes the `EXPORT` command is sent to a different process of the external remote
than the following `TRANSFEREXPORT` command.
As a result, one process receives two `EXPORT`s in a row, the first of which it ignores,
while some other process receives a `TRANSFEREXPORT` without a prior `EXPORT`,
reusing whatever filename was set in the previous transaction,
and either ovewriting the last accessed remote file with the wrong content,
or retrieving the content of the last accessed remote file instead of the one git-annex wanted.
Or I misunderstood the protocol - please tell me if that's the case.
### What steps will reproduce the problem?
I don't have a minimal reproducing example.
I was working on adding tree export support to git-annex-remote-rclone,
and its the testsuite on my branch can reproduce the problem around half of the time, but only on MacOS.
It seems like it's a race condition and the interleaving that triggers it doesn't happen on Linux
Here's an example test run when it fails
[on github](https://github.com/Wolf480pl/git-annex-remote-rclone/actions/runs/4525558194/jobs/7970140554)
and the test code - [on github](https://github.com/Wolf480pl/git-annex-remote-rclone/blob/bd1a497fca8614286ec290bb557c83442c0e23c9/tests/all-in-one.sh#L224)
and as [[an attachment|all-in-one.sh]]
### What version of git-annex are you using? On what operating system?
git-annex version: 10.20230227
OS: macOS 12.6.3 21G419
### Please provide any additional information below.
Full log is quite long so I put it in [[an attachment|annex-rclone.log]]
and also on github gists in case anyone prefers that:
https://gist.github.com/Wolf480pl/4bdc83e23154827aad46e84bad631419
Here are the interesting parts:
First, during the tree export, we see an example of correct upload of the `test 9.dat` and `test 10.dat` files:
[[!format txt """
2023-03-26T16:34:52.2551390Z [2023-03-26 16:34:52.085377] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[3] <-- EXPORT test 9.dat
2023-03-26T16:34:52.2653060Z [2023-03-26 16:34:52.086085] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[3] <-- TRANSFEREXPORT STORE SHA256E-s7--a30e9d26ce633b40da3ba8cd8806b9b349cb6c3de6816c6d64f85a571012a973.dat .git/annex/objects/zZ/kw/SHA256E-s7--a30e9d26ce633b40da3ba8cd8806b9b349cb6c3de6816c6d64f85a571012a973.dat/SHA256E-s7--a30e9d26ce633b40da3ba8cd8806b9b349cb6c3de6816c6d64f85a571012a973.dat
[...]
2023-03-26T16:34:49.9382650Z [2023-03-26 16:34:49.629684] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[3] <-- EXPORT test 10.dat
2023-03-26T16:34:49.9384770Z [2023-03-26 16:34:49.629761] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[3] <-- TRANSFEREXPORT STORE SHA256E-s8--d5624694cf1515bdf8c3a648ae35d64f4bdff934800a22a070c6d0baddc120b0.dat .git/annex/objects/6k/X3/SHA256E-s8--d5624694cf1515bdf8c3a648ae35d64f4bdff934800a22a070c6d0baddc120b0.dat/SHA256E-s8--d5624694cf1515bdf8c3a648ae35d64f4bdff934800a22a070c6d0baddc120b0.dat
"""]]
so we know that key of `test 9.dat` is `a30e...973.dat`, and for `test 10.dat` it's `d56...0b0.dat`
Then, during the get, we see the bug happen:
[[!format txt """
2023-03-26T16:34:55.4392510Z [2023-03-26 16:34:54.534833] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[5] --> TRANSFER-SUCCESS RETRIEVE SHA256E-s8--fbb0a327e1528cdb3214abb2ec3fb1dd97cc39dfc12751df102eca019f602e73.dat
2023-03-26T16:34:55.4394480Z [2023-03-26 16:34:54.53532] (Annex.Perms) freezing content .git/annex/objects/45/Gp/SHA256E-s8--91d9183c1a8f61526ed68c5357d52a719481ccbba5039f815cf8f71ae4edbf24.dat/SHA256E-s8--91d9183c1a8f61526ed68c5357d52a719481ccbba5039f815cf8f71ae4edbf24.dat
2023-03-26T16:34:55.4395900Z [2023-03-26 16:34:54.545524] (Annex.Branch) read b51/a3b/SHA256E-s7--a30e9d26ce633b40da3ba8cd8806b9b349cb6c3de6816c6d64f85a571012a973.dat.log
2023-03-26T16:34:55.4397280Z [2023-03-26 16:34:54.545836] (Annex.Perms) freezing content directory .git/annex/objects/45/Gp/SHA256E-s8--91d9183c1a8f61526ed68c5357d52a719481ccbba5039f815cf8f71ae4edbf24.dat
2023-03-26T16:34:55.4398630Z [2023-03-26 16:34:54.54609] (Annex.Branch) read 253/975/SHA256E-s8--91d9183c1a8f61526ed68c5357d52a719481ccbba5039f815cf8f71ae4edbf24.dat.log
2023-03-26T16:34:55.4399950Z [2023-03-26 16:34:54.5477] (Annex.Branch) set 253/975/SHA256E-s8--91d9183c1a8f61526ed68c5357d52a719481ccbba5039f815cf8f71ae4edbf24.dat.log
2023-03-26T16:34:55.4401900Z [2023-03-26 16:34:54.558828] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[2] --> TRANSFER-SUCCESS RETRIEVE SHA256E-s7--b163189df1a08d63ba85e1566799cf07ca2de3865ac97a85b2b2d0cbfbd9a2f3.dat
2023-03-26T16:34:55.4403360Z [2023-03-26 16:34:54.559391] (Annex.Branch) read c9a/21e/SHA256E-s8--128888bb8975fc51a7fd410322b088593e158b37a24973483da2ad17fb6d7ff5.dat.log
2023-03-26T16:34:55.4405510Z [2023-03-26 16:34:54.561866] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[2] <-- EXPORT test 9.dat
2023-03-26T16:34:55.4407810Z [2023-03-26 16:34:54.561942] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[2] <-- EXPORT test 10.dat
2023-03-26T16:34:55.4409480Z [2023-03-26 16:34:54.561946] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[5] <-- TRANSFEREXPORT RETRIEVE SHA256E-s7--a30e9d26ce633b40da3ba8cd8806b9b349cb6c3de6816c6d64f85a571012a973.dat .git/annex/tmp/SHA256E-s7--a30e9d26ce633b40da3ba8cd8806b9b349cb6c3de6816c6d64f85a571012a973.dat
2023-03-26T16:34:55.4411390Z [2023-03-26 16:34:54.562032] (Annex.ExternalAddonProcess) /Users/runner/work/git-annex-remote-rclone/git-annex-remote-rclone/git-annex-remote-rclone[2] <-- TRANSFEREXPORT RETRIEVE SHA256E-s8--d5624694cf1515bdf8c3a648ae35d64f4bdff934800a22a070c6d0baddc120b0.dat .git/annex/tmp/SHA256E-s8--d5624694cf1515bdf8c3a648ae35d64f4bdff934800a22a070c6d0baddc120b0.dat
"""]]
As you can see in the last 4 lines:
* process 2 got `EXPORT test 9.dat` and then immediately `EXPORT test 10.dat`
* then process 5 got the `TRANSFEREXPORT` command for the `test 9.dat` file (`a30..973.dat`)
* process 5 did not, prior to this transfer, receive any `EXPORT` command since its last transfer of an unrelated file (see `TRANSFER-SUCCESS` in the first quoted line).
* so it was still holding the old filename from that unrelated transfer
* then, process 2 receives a (correct) `TRANSFEREXPORT` for the `test 10.dat` file (`d56...0b0.dat`).
It appears that the `EXPORT test 9.dat` should've been sent to process 5 instead of process 2.
But since it wasn't, process 5 retrieved the wrong file into what git-annex expected to be `test 9.dat`.
### 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)
I really wanted to use git annex for my media storage, it seems like the project I've been looking for for years.
But I first needed to be able to exporttree over FTP.
(I have a cheap NAS is terribly slow at encryption (SSH, etc) so I'm using FTP to get reasonable speeds with it.)
So I thought I'd implement it and then hit this bug.