Closed yarikoptic closed 1 year ago
@yarikoptic
The timestamps that are actually compared are the Dandiset's modified
property and the timestamp stored in .dandi/assets-state.json
.
could you please add more information into exception, in particular the actual datetimes claimed to be "not updated"?
If you want to see the actual values there, that would involve constantly passing around the timestamps to every corner of the code. I could instead log the timestamps at the start of processing the Dandiset.
ok, but why then was that errorred run? BTW now I see that it has commit since then but log message meaning is not clear to me:
(base) dandi@drogon:/mnt/backup/dandi/dandisets/000350$ git log -1 -p
commit 9d10b8722d5c8b28c3b63de9f0e8bcb0ce496f34 (HEAD -> draft, github/draft)
Author: DANDI User <info@dandiarchive.org>
Date: Wed Nov 2 05:02:24 2022 +0000
[backups2datalad] 1 asset not yet downloaded
diff --git a/.dandi/assets-state.json b/.dandi/assets-state.json
index d24a77a..193639b 100644
--- a/.dandi/assets-state.json
+++ b/.dandi/assets-state.json
@@ -1,3 +1,3 @@
{
- "timestamp": "2022-11-02T05:01:33.196375+00:00"
+ "timestamp": "2022-11-02T05:02:24.034137+00:00"
}
since we do not download any assets, we do produce files for them, and paths are there
(base) dandi@drogon:/mnt/backup/dandi/dandisets/000350$ grep -A1 path .dandi/assets.json | sed -ne 's/"\(sub.*\)",/\1/p' | xargs ls -l
lrwxrwxrwx 1 dandi dandi 211 Oct 31 15:02 sub-20170113-2/sub-20170113-2_ses-20160113_2_1_cy14_7dpf_0gain_trial_20170113_124907_ophys.nwb -> ../.git/annex/objects/35/14/SHA256E-s335309669648--3357eb187521de7c34df82bb14ee35aa57f260d7a152532f363c52ba9f7173d9.nwb/SHA256E-s335309669648--3357eb187521de7c34df82bb14ee35aa57f260d7a152532f363c52ba9f7173d9.nwb
lrwxrwxrwx 1 dandi dandi 211 Oct 31 15:02 sub-20170113-2/sub-20170113-2_ses-20160113_2_1_cy14_7dpf_0gain_trial_20170113_124907_ophys.nwb -> ../.git/annex/objects/35/14/SHA256E-s335309669648--3357eb187521de7c34df82bb14ee35aa57f260d7a152532f363c52ba9f7173d9.nwb/SHA256E-s335309669648--3357eb187521de7c34df82bb14ee35aa57f260d7a152532f363c52ba9f7173d9.nwb
lrwxrwxrwx 1 dandi dandi 211 Nov 2 01:02 sub-20170113-3/sub-20170113-3_ses-20160113_3_1_cy14_7dpf_0gain_trial_20170113_150834_ophys.nwb -> ../.git/annex/objects/gg/w9/SHA256E-s430338126638--de5eed79aa1f5c6d8a3bc045eebc7a6d32be0bff9056b43ca1eccecf88e0392a.nwb/SHA256E-s430338126638--de5eed79aa1f5c6d8a3bc045eebc7a6d32be0bff9056b43ca1eccecf88e0392a.nwb
lrwxrwxrwx 1 dandi dandi 211 Nov 2 01:02 sub-20170113-3/sub-20170113-3_ses-20160113_3_1_cy14_7dpf_0gain_trial_20170113_150834_ophys.nwb -> ../.git/annex/objects/gg/w9/SHA256E-s430338126638--de5eed79aa1f5c6d8a3bc045eebc7a6d32be0bff9056b43ca1eccecf88e0392a.nwb/SHA256E-s430338126638--de5eed79aa1f5c6d8a3bc045eebc7a6d32be0bff9056b43ca1eccecf88e0392a.nwb
so what is the meaning of that log message? note that there is difference from state in the archive -- that only 3 assets are there now
(base) dandi@drogon:/mnt/backup/dandi/dandisets/000350$ curl --silent https://api.dandiarchive.org/api/dandisets/000350/versions/draft/assets/ | jq . | grep path
"path": "sub-20170113-2/sub-20170113-2_ses-20160113_2_1_cy14_7dpf_0gain_trial_20170113_124907_ophys.nwb",
"path": "sub-20170113-3/sub-20170113-3_ses-20160113_3_1_cy14_7dpf_0gain_trial_20170113_150834_ophys.nwb",
"path": "sub-20170113-4/sub-20170113-4_ses-20160113_4_1_cy14_7dpf_0gain_trial_20170113_171241_ophys.nwb",
mystery...?
@yarikoptic
assets-state.json
was 2022-11-02, and the Dandiset's modified
date was 2022-10-30, then any discrepancies between the backup and the Archive would cause an error in "verify" mode.still things do not quite add up for me on why verify
was errorring out ... I reran to the same result. then I reran with --mode force
-- that fixed it (we got only 3 assets now) and --mode verify
succeed after...
I will close this for now but smells to me like it might come back ...
we have got a similar fresh error
Date: Thu, 03 Nov 2022 01:58:11 -0400
From: Cron Daemon <root@drogon.datalad.org>
To: dandi@drogon.datalad.org
Subject: Cron <dandi@drogon> chronic flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron.lock bash -c '/mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify'
2022-11-03T01:53:51-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000148/versions/draft/ in 1.019917 seconds as it raised ReadTimeout:
2022-11-03T01:54:19-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000149/versions/draft/ in 0.961400 seconds as it raised ReadTimeout:
2022-11-03T01:57:49-0400 [ERROR ] backups2datalad: Job failed on input <Dandiset 000350/draft>:
Traceback (most recent call last):
File "/mnt/backup/dandi/dandisets/tools/backups2datalad/aioutil.py", line 189, in dowork
outp = await func(inp)
File "/mnt/backup/dandi/dandisets/tools/backups2datalad/datasetter.py", line 153, in update_dandiset
changed = await self.sync_dataset(
File "/mnt/backup/dandi/dandisets/tools/backups2datalad/datasetter.py", line 188, in sync_dataset
await syncer.sync_assets(error_on_change)
File "/mnt/backup/dandi/dandisets/tools/backups2datalad/syncer.py", line 36, in sync_assets
self.report = await async_assets(
File "/mnt/backup/dandi/dandisets/tools/backups2datalad/asyncer.py", line 499, in async_assets
nursery.start_soon(dm.read_addurl)
File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 662, in __aexit__
raise exceptions[0]
File "/mnt/backup/dandi/dandisets/tools/backups2datalad/asyncer.py", line 232, in process_asset
raise UnexpectedChangeError(
tools.backups2datalad.util.UnexpectedChangeError: Metadata for asset sub-20170113-3/sub-20170113-3_ses-20160113_3_1_cy14_7dpf_0gain_trial_20170113_150834_ophys.nwb was changed/added but draft timestamp was not updated on server
@jwodder could you please troubleshoot it ?
@yarikoptic The modified
timestamp for the asset in question changed from 2022-11-02T22:35:46.804195Z
to 2022-11-03T13:51:02.489892Z
(with no other changes to the properties or metadata), yet the Dandiset's (EDIT: draft's) modified
timestamp remained at 2022-11-02T22:25:17.710281Z
, the same as the value stored in .dandi/assets-state.json
.
@yarikoptic The
modified
timestamp for the asset in question changed from2022-11-02T22:35:46.804195Z
to2022-11-03T13:51:02.489892Z
(with no other changes to the properties or metadata), yet the Dandiset'smodified
timestamp remained at2022-11-02T22:25:17.710281Z
, the same as the value stored in.dandi/assets-state.json
.
so it smells like a bug in dandi-archive or our assumption on what changes the modified
of the dandiset, correct? in either case -- something to clarify with @dandi/archive-maintainers: shouldn't a modification of an asset which lead to modification of asset's modified
timestamp modify dandiset's modified
timestamp?
so it smells like a bug in dandi-archive or our assumption on what changes the
modified
of the dandiset, correct? in either case -- something to clarify with @dandi/archive-maintainers: shouldn't a modification of an asset which lead to modification of asset'smodified
timestamp modify dandiset'smodified
timestamp?
This behavior was never implemented. If that's desired, it could be changed. To clarify
modified
timestamp of the draft version and dandiset?modified
timestamp then as well?@AlmightyYakob
This behavior was never implemented.
Interesting, seeing as you stated here:
Currently a draft version's
modified
field is updated every time an asset within that draft version is created, updated or destroyed.
Did this change since then, or were you simply wrong at the time? Or is this a matter of certain things not counting as "updates"?
Currently a draft version's
modified
field is updated every time an asset within that draft version is created, updated or destroyed.Did this change since then, or were you simply wrong at the time? Or is this a matter of certain things not counting as "updates"?
That is still true, the draft version 'modified' field is updated whenever an asset is created/updated/destroyed, but the dandiset modified
field is not.
@AlmightyYakob But the backup script already uses the draft version's modified
property to decide how to proceed. "The Dandiset's modified
timestamp" in this comment should actually be "the Dandiset's draft's modified
timestamp."
@AlmightyYakob But the backup script already uses the draft version's
modified
property to decide how to proceed. "The Dandiset'smodified
timestamp" in this comment should actually be "the Dandiset's draft'smodified
timestamp."
Oh I see, in that case I'm not sure what's to blame. I can confirm that for all three asset operations, the version is saved, which updates the modified
timestamp. So for an asset to be updated yet the version not, there would have needed to be some exception in the API call itself that would prevent the version save from happening.
I'm looking into this now, is this potentially buggy behavior blocking anything?
I'm looking into this now, is this potentially buggy behavior blocking anything?
"just" blocking dataladification and archive of the 000350 dandiset, and results in a daily email with the error, while all other dandisets somehow backup no problem.
"just" blocking dataladification and archive of the 000350 dandiset, and results in a daily email with the error, while all other dandisets somehow backup no problem.
What would unblock you? Would a simple update of the draft version (saving with updated timestamp and metadata) suffice?
Note that there's been activity on Dandiset 000350 in the last few hours, so its modified
timestamp has updated again, so further backups in "verify" mode should succeed unless the problem is recurring.
"just" blocking dataladification and archive of the 000350 dandiset, and results in a daily email with the error, while all other dandisets somehow backup no problem.
What would unblock you? Would a simple update of the draft version (saving with updated timestamp and metadata) suffice?
I already did forced update yesterday which resolved it for time being, but then due to ongoing activity (as @jwodder just confirmed) things "shifted" again, so there is something in the archive and this dandiset in particular which causes it to get into this finicky state -- so there would be no guarantees that I am not "blocked" again.
FTR: a new gotcha for this dandiset -- https://github.com/dandi/dandi-archive/issues/1355 (attn @AlmightyYakob )
now we got hit with the same issue in 000346 totaling in anyio._backends._asyncio.ExceptionGroup: 39 exceptions were raised in the task group:
.
hopefully this issue is addressed going forward by https://github.com/dandi/dandi-archive/pull/1366 but we might need to "touch" those affected dandisets
ATM somewhat blocked by #304 no more
Since nov 9th (which seems to be before https://github.com/dandi/dandi-archive/pull/1366) we keep getting
anyio._backends._asyncio.ExceptionGroup: 39 exceptions were raised in the task group:
----------------------------
Traceback (most recent call last):
File "/mnt/backup/dandi/dandisets/tools/backups2datalad/asyncer.py", line 232, in process_asset
raise UnexpectedChangeError(
tools.backups2datalad.util.UnexpectedChangeError: Dandiset 000341: Metadata for asset In_vitro_oscillation_Rat/sub-1610102tm/sub-1610102tm_ses-1610102tm-1-3,12-4_icephys.nwb was changed/added but draft timestamp was not updated on server
...
❯ curl --silent -X 'GET' 'https://api.dandiarchive.org/api/dandisets/000341/' -H 'accept: application/json' | jq | grep modified
"modified": "2022-09-29T09:01:51.498890Z",
"modified": "2022-11-07T13:55:48.929812Z",
"modified": "2022-09-29T09:01:51.498890Z",
so I went and touched its metadata record (added space/save/remove space/save) and got modified updated
❯ curl --silent -X 'GET' 'https://api.dandiarchive.org/api/dandisets/000341/' -H 'accept: application/json' | jq | grep modified
"modified": "2022-09-29T09:01:51.498890Z",
"modified": "2022-11-22T13:51:07.906466Z",
"modified": "2022-09-29T09:01:51.498890Z",
but then attempt to back it up lead to https://github.com/dandi/dandisets/issues/306 .
With all that, since I think we did not see this UnexpectedChangeError on any other dandiset and presumably underlying issue was addressed -- closing
Just making record that recent run erorred out with
and it is a fresh asset which has
and we have
so only
dateCreated
for that version in endpoint for it but we do have modified inand it is
2022-10-31T18:07:40.901143Z
whenever asset had modified"2022-10-31T17:46:44.852094+00:00"
which is before then so might be all logical, in that may be or not (since we do not have provenance) time stamp was modified appropriately.From the logged exception it is impossible to resolve the ambiguity... @jwodder could you please add more information into exception, in particular the actual datetimes claimed to be "not updated"?
But I also suspect a bug in our logic, since I have reran the invocation for that dandiset and got the same error:
```shell (base) dandi@drogon:/mnt/backup/dandi/dandisets/000350$ flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron.lock bash -c '/mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify 000350' 2022-11-01T10:54:42-0400 [ERROR ] backups2datalad: Job failed on input