Closed yarikoptic closed 1 year ago
yesterday
@jwodder please check those logs - may be now they have more relevant info after #348 ? meanwhile I mv 000467 .git/_errored_
so next cron job may be would try again create it instead of just erroring out due to a dirty state.
On rerun had the same locking issue, so nicely reproducible , log /mnt/backup/dandi/dandisets/.git/dandi/backups2datalad/2023.05.15.04.02.07Z.log
@yarikoptic I can't tell why git rm
failed initially, but I think it may be a good idea to lock the AsyncDataset for all of AsyncDataset.remove()
so that, if a git rm
fails, no other git rm
s can run and mess with the lockfile before fuser
is done doing its thing.
refs:
I guess it is still one of those processes it is in "conflict" with, and most likely addurl
... Strangely I see two processes being terminated:
2023-05-13T17:04:40-0400 [DEBUG ] backups2datalad: Waiting for `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] to terminate
2023-05-13T17:04:47-0400 [DEBUG ] backups2datalad: Waiting for `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] to terminate
2023-05-13T17:04:47-0400 [DEBUG ] backups2datalad: Command `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] exited with return code 0
or is that "Waiting" could be printed multiple times?
In https://github.com/dandi/dandisets/pull/345 we added join locking on rm
and addurl
. But surprisingly I do not see any "Downloading" log line
dandi@drogon:/mnt/backup/dandi/dandisets$ grep Downloading /mnt/backup/dandi/dandisets/.git/dandi/backups2datalad/2023.05.13.21.02.07Z.log
dandi@drogon:/mnt/backup/dandi/dandisets$
which I would expect to see from hitting this line https://github.com/dandi/dandisets/pull/345/files#diff-7c4a8c0f1a1067d11633a1b97a012f1813e7ea0c071be8a890f2fb5ef1d8c8f9R386 in feed_addurl
. Is that expected to have addurl
running but not hitting this line?
In https://github.com/dandi/dandisets/issues/342#issuecomment-1511370098 you nicely describe that we do addurl
only for files which go to git
instead of git-annex
. But if there is no Downloading
as per above, may be we do not even need to have it running, but we start it ahead of time at https://github.com/dandi/dandisets/blob/HEAD/tools/backups2datalad/asyncer.py#L481 . Could we delay starting it until there is actual need to have it started? (the check/start I guess should be locked to avoid multiple starts)?
In https://github.com/dandi/dandisets/issues/342#issuecomment-1500463609 I suggested for us to simply retry that rm
. But I think we never exercised that opportunity. Could you please add retrying the rm
e.g. up to 5 times spreading into up to a minute or so?
@yarikoptic
addurl
is always run for a Dandiset even if it's not needed due to the Dandiset only containing binary files. I'm going to try delaying running addurl
until it's needed.@yarikoptic
- I don't know why the "Waiting for addurl" line was printed twice.
please try to figure it out or add more logging (when starting addurl
and/or initiating those shutdowns) -- since we seems to not do much for those processes:
dandi@drogon:~$ grep 'addurl' /mnt/backup/dandi/dandisets/.git/dandi/backups2datalad/2023.05.13.21.02.07Z.log
2023-05-13T17:02:19-0400 [DEBUG ] backups2datalad: Opening pipe to `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467]
2023-05-13T17:04:40-0400 [DEBUG ] backups2datalad: Waiting for `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] to terminate
2023-05-13T17:04:47-0400 [DEBUG ] backups2datalad: Waiting for `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] to terminate
2023-05-13T17:04:47-0400 [DEBUG ] backups2datalad: Command `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] exited with return code 0
wild guess - since we hit that index.lock
for two files, we initiate that shutdown of batched processes twice. I guess we might want/need locking there too?
wild guess - since we hit that
index.lock
for two files, we initiate that shutdown of batched processes twice. I guess we might want/need locking there too?
wrong -- in the most recent run after PR merge we failed with a single index.lock problem but still got that message twice
dandi@drogon:~$ grep 'File exi' /mnt/backup/dandi/dandisets/.git/dandi/backups2datalad/2023.05.15.14.02.06Z.log
fatal: Unable to create '/mnt/backup/dandi/dandisets/000467/.git/index.lock': File exists.
dandi@drogon:~$ grep 'addurl.*000467' /mnt/backup/dandi/dandisets/.git/dandi/backups2datalad/2023.05.15.14.02.06Z.log
2023-05-15T10:02:19-0400 [DEBUG ] backups2datalad: Opening pipe to `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467]
2023-05-15T10:04:44-0400 [DEBUG ] backups2datalad: Waiting for `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] to terminate
2023-05-15T10:04:52-0400 [DEBUG ] backups2datalad: Waiting for `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] to terminate
2023-05-15T10:04:52-0400 [DEBUG ] backups2datalad: Command `git -c receive.autogc=0 -c gc.auto=0 annex addurl -c annex.alwayscompact=false --batch --with-files --jobs 5 --json --json-error-messages --json-progress --raw` [cwd=/mnt/backup/dandi/dandisets/000467] exited with return code 0
@yarikoptic I think I know why we're getting two "Waiting for addurl" messages. The method that reads addurl
's output wraps it in aclosing()
, so its aclose()
method (which emits the message) gets called when finished reading or when cancelling everything, and then addurl
's aclose()
is called again when this async with
block exits. Calling aclose()
twice appears to be harmless, but I've removed the aclosing()
line just in case.
@yarikoptic How exactly should retrying git rm
work? Should the lock be kept across retries? Should fuser
be called after every attempt or only after the last one? Should the result of the fuser
call influence whether we keep retrying?
@yarikoptic How exactly should retrying
git rm
work? Should the lock be kept across retries?
I don't have idea/preference ATM -- so whatever way would be the simplest
Should
fuser
be called after every attempt or only after the last one?
probably after each one. So far IIRC it was never informative though.
Should the result of the
fuser
call influence whether we keep retrying?
I don't think so.
ok, for now, and again, let's consider that #352 has put some final period
in this issue ;)
Originally reported in #346, and I thought that precommit'ing would resolve it in 1e24823928154e62077c5abb41dbb00ad9fcb094 but it didn't (fully at least). We ended up with cron job failing
and indeed prior one had the same symptoms as before
I think the next step would be to instrument it so we do know which command spits out that
warning but I wonder how without raising the logging to DEBUG level "on the screen" - log file already has it at DEBUG level but
datalad
(I do not see any log from datalad)ideas @jwodder ?