FOI: backups2datalad-update-cron --mode verify got stuck
- Dominant language
- Python
- Stars
- 0
- Forks
- 1
- Avg merge
- 2d 16h
- Merged PRs (30d)
- 5
Description
Today is June 7 and I spotted that last update to dandisets was in May... I see that there is still process running
```
root 3911865 0.0 0.0 8804 1548 ? Ss Mar26 0:32 /usr/sbin/cron -f
root 4052378 0.0 0.0 9740 1856 ? S May25 0:00 /usr/sbin/CRON -f
dandi 4052380 0.0 0.0 2484 408 ? Ss May25 0:00 /bin/sh -c chronic flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron-nonzarr.lock bash -c '/mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify'
dandi 4052383 0.0 0.0 18640 5980 ? S May25 4:25 /usr/bin/perl /usr/bin/chronic flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron-nonzarr.lock bash -c /mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify
dandi 4052385 0.0 0.0 5548 472 ? S May25 0:00 /usr/bin/flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron-nonzarr.lock bash -c /mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify
dandi 4052386 0.0 0.0 6952 2060 ? S May25 0:00 /bin/bash /mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify
dandi 4052695 0.0 0.0 6952 748 ? S May25 0:00 /bin/bash /mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify
dandi 4059070 0.0 0.6 1499228 448460 ? Dl May25 3:29 /home/dandi/miniconda3/envs/dandisets-2/bin/python /home/dandi/miniconda3/envs/dandisets-2/bin/backups2datalad -l WARNING --backup-root /mnt/backup/dandi --config tools/backups2datalad.cfg.yaml update-from-backup --workers 5 -e 000(026|108|243|876)$ --mode verify
dandi 4059071 0.0 0.0 6384 2248 ? S May25 0:00 grep -v nothing to save, working tree clean
```
and looking at the log `/mnt/backup/dandi/dandisets/.git/dandi/backups2datalad/2024.05.25.05.53.54Z.log` I see lots of
```
2024-06-06T05:21:13-0400 [DEBUG ] backups2datalad: Finished [rc=1]: git -c receive.autogc=0 -c gc.auto=0 config --file .datalad/config --get dandi.dandiset.embargo-status [cwd=/mnt/backup/dandi/dandisets/001022]
2024-06-06T05:21:13-0400 [INFO ] backups2datalad: Dandiset 001022: Updating metadata file
2024-06-06T05:22:13-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 1.001618 seconds as it raised PoolTimeout:
2024-06-06T05:23:14-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 1.903866 seconds as it raised PoolTimeout:
2024-06-06T05:24:16-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 4.186317 seconds as it raised PoolTimeout:
2024-06-06T05:25:21-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 7.632318 seconds as it raised PoolTimeout:
2024-06-06T05:26:18-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000989/versions/draft/ in 487.782007 seconds as it raised PoolTimeout:
2024-06-06T05:26:28-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 15.465852 seconds as it raised PoolTimeout:
2024-06-06T05:27:44-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 30.563104 seconds as it raised PoolTimeout:
2024-06-06T05:29:14-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 65.885731 seconds as it raised PoolTimeout:
2024-06-06T05:29:50-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000988/versions/draft/ in 989.482749 seconds as it raised PoolTimeout:
2024-06-06T05:31:20-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 129.670206 seconds as it raised PoolTimeout:
2024-06-06T05:34:30-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 265.165215 seconds as it raised PoolTimeout:
2024-06-06T05:35:26-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000989/versions/draft/ in 1043.047437 seconds as it raised PoolTimeout:
2024-06-06T05:39:56-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 494.584960 seconds as it raised PoolTimeout:
2024-06-06T05:47:20-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000988/versions/draft/ in 2034.338609 seconds as it raised PoolTimeout:
2024-06-06T05:49:10-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 1017.563094 seconds as it raised PoolTimeout:
2024-06-06T05:53:49-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000989/versions/draft/ in 2058.971743 seconds as it raised PoolTimeout:
2024-06-06T06:07:08-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/001022/versions/draft/ in 2065.306574 seconds as it raised PoolTimeout:
2024-06-06T06:22:14-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000988/versions/draft/ in 4080.329725 seconds as it raised PoolTimeout:
2024-06-06T06:29:08-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000989/versions/draft/ in 4039.886215 seconds as it raised PoolTimeout:
2024-06-06T06:39:52-0400 [ERROR ] backups2datalad: Job failed on input :
Traceback (most recent call last):
File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/anyio/_core/_tasks.py", line 115, in fail_after
yield cancel_scope
File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/httpcore/_synchronization.py", line 123, in wait
await self._anyio_event.wait()
File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/anyio/_backends/_asyncio.py", line 1621, in wait
await self._event.wait()
File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/asyncio/locks.py", line 213, in wait
await fut
asyncio.exceptions.CancelledError: Cancelled by cancel scope 7f1ccdb91cf0
```
which if ran on command line passes just fine and quick (`curl -X 'GET' \
'https://api.dandiarchive.org/api/dandisets/000988/versions/draft/' \
-H 'accept: application/json'`)
I wonder now if that is related to that network switch changeover / MTU fiasco, but I can't fathom why/how it would affect this process specifically. I will interrupt it now and do update without verify "manually" and then will do with verify (unless cron beats me to those)... drogon overall seems a bit overwhelmed ATM as well :-/
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with the backups2datalad-update-cron entry point and its update-from-backup --mode verify invocation, then compare the cron run with the command-line request shown in the issue. Inspect tools/backups2datalad.cfg.yaml and the referenced backups2datalad log for the PoolTimeout sequence. Done means the verify job completes rather than remaining stuck, with the cause and reproduction or validation documented.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- bash, python
- Domain
- backend, devops, networking
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100