Doesn't update superdataset properly any more. backups2datalad process is "stuck"

[yarikoptic]

I noticed that https://github.com/dandi/dandisets says that last commit was 3 weeks ago. But we have lots of recently updated dandisets:

Individual dandiset github repos seems also have recent updates

on drogon I see only some not pushed (why?) updates to 000026 in dandisets superdataset

dandi@drogon:/mnt/backup/dandi/dandisets$ git log github/draft..draft
commit a60c7bf88d82a350f538bd83594c163a3b29e51e (HEAD -> draft)
Author: DANDI Team <team@dandiarchive.org>
Date:   Wed Mar 27 03:25:33 2024 -0400

    1 updated (000026)
    
    000026:
     - [backups2datalad] 22 files added, 10 files updated

commit df1dce3a6fe1aa954dd818ce54420ab31b07e71d
Author: DANDI Team <team@dandiarchive.org>
Date:   Tue Mar 26 04:10:35 2024 -0400

    1 updated (000026)
    
    000026:
     - [backups2datalad] 229 files added, 29 files updated

and git status shows that MANY dandisets have uncommitted changes (new commits OR modified content!!) on drogon

dandi@drogon:/mnt/backup/dandi/dandisets$ git status
Refresh index: 100% (612/612), done.
On branch draft
Your branch is ahead of 'github/draft' by 2 commits.
  (use "git push" to publish your local commits)

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git restore <file>..." to discard changes in working directory)
  (commit or discard the untracked or modified content in submodules)
        modified:   000018 (new commits)
        modified:   000024 (new commits)
        modified:   000029 (modified content)
        modified:   000030 (new commits)
        modified:   000031 (new commits)
        modified:   000032 (new commits)
        modified:   000033 (new commits)
        modified:   000038 (new commits)
        modified:   000040 (new commits)
        modified:   000042 (new commits)
...

so most likely recent changes on handling embargoed/public dandisets broke this...
Then I looked at ps on drogon -- and apparently there is still a process which runs in --verify mode since Mar 07!

As such it seems to be stuck:

dandi    2645263  0.0  0.0   2484   404 ?        Ss   Mar07   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    2645264  0.0  0.0  19748  5512 ?        S    Mar07   7:09       /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    2645317  0.0  0.0   5548   544 ?        S    Mar07   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    2645318  0.0  0.0   6952  2536 ?        S    Mar07   0:00           /bin/bash /mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify
dandi    2650110  0.0  0.0   6952  1240 ?        S    Mar07   0:00             /bin/bash /mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify
dandi    2650139  0.0  0.3 1790364 200180 ?      Sl   Mar07   1:21               /home/dandi/miniconda3/envs/dandisets-2/bin/python3.1 /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)$ --mode verify
dandi    2650140  0.0  0.0   6384  2272 ?        S    Mar07   0:00               grep -v nothing to save, working tree clean

py-spy'ing that process gives no useful detail

then I recalled that we have logs! and this is what I see

(dandisets-2) dandi@drogon:/mnt/backup/dandi/dandisets$ tail -f .git/dandi/backups2datalad/2024.03.07.06.50.32Z.log
2024-03-29T03:12:15-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000729/versions/draft/ in 4292.823660 seconds as it raised PoolTimeout: 
2024-03-29T03:34:24-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000726/versions/draft/ in 8515.649940 seconds as it raised PoolTimeout: 
2024-03-29T04:12:28-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000727/versions/draft/ in 7882.410218 seconds as it raised PoolTimeout: 
2024-03-29T04:19:15-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000728/versions/draft/ in 8402.162677 seconds as it raised PoolTimeout: 
2024-03-29T04:24:48-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000729/versions/draft/ in 8413.961004 seconds as it raised PoolTimeout: 
2024-03-29T05:34:07-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000725/versions/draft/ in 15890.092814 seconds as it raised PoolTimeout: 
2024-03-29T05:57:19-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000726/versions/draft/ in 17122.589867 seconds as it raised PoolTimeout: 
2024-03-29T06:24:50-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000727/versions/draft/ in 17075.343311 seconds as it raised PoolTimeout: 
2024-03-29T06:40:18-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000728/versions/draft/ in 16793.199329 seconds as it raised PoolTimeout: 
2024-03-29T06:46:02-0400 [WARNING ] backups2datalad: Retrying GET request to /dandisets/000729/versions/draft/ in 17087.073695 seconds as it raised PoolTimeout: 

some seems to be open (000726) and some embargoed (000729) but even for embargoed endpoint seems to work just fine:

❯ curl -X 'GET' 'https://api.dandiarchive.org/api/dandisets/000729/versions/draft/' -H 'accept: application/json'
{"detail":"Authentication credentials were not provided."}%  

so seems like a bug somewhere.

[jwodder]

I think this may be caused by one or more bugs in httpx (possibly this one) for which fixes have been released, but the version of httpx in the dandisets-2 env is not the latest. I suggest killing the backup process and updating all of the packages before starting a new process; I believe the latter step can be accomplished by adding the option --upgrade-strategy eager to this line.

[yarikoptic]

ok, I will try to do that now

• kill process
• git reset --hard all repos with modified content, see that they are clean
• commit updated state of superdataset
• modify cron with --upgrade-strategy eager
• redo the cron

[yarikoptic]

--upgrade-strategy eager added to installation of backups2datalad had no effect on httpx

(dandisets-2) dandi@drogon:/mnt/backup/dandi/dandisets$ pip show httpx | grep Version; chronic pip uninstall --yes backups2datalad; pip install --upgrade-strategy eager git+https://github.com/dandi/backups2datalad | grep httpx; pip show httpx | grep Version
Version: 0.25.1
  Running command git clone --filter=blob:none --quiet https://github.com/dandi/backups2datalad /tmp/pip-req-build-usy7krrb
Requirement already satisfied: httpx~=0.22 in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from backups2datalad==0.0.0) (0.25.1)
Requirement already satisfied: certifi in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpx~=0.22->backups2datalad==0.0.0) (2022.12.7)
Requirement already satisfied: httpcore in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpx~=0.22->backups2datalad==0.0.0) (1.0.2)
Requirement already satisfied: h11<0.15,>=0.13 in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpcore->httpx~=0.22->backups2datalad==0.0.0) (0.14.0)
Version: 0.25.1

so I just manually upgraded it:

(dandisets-2) dandi@drogon:/mnt/backup/dandi/dandisets$ pip install --upgrade httpx
Requirement already satisfied: httpx in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (0.25.1)
Collecting httpx
  Downloading httpx-0.27.0-py3-none-any.whl.metadata (7.2 kB)
Requirement already satisfied: anyio in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpx) (4.0.0)
Requirement already satisfied: certifi in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpx) (2022.12.7)
Requirement already satisfied: httpcore==1.* in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpx) (1.0.2)
Requirement already satisfied: idna in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpx) (3.4)
Requirement already satisfied: sniffio in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpx) (1.3.0)
Requirement already satisfied: h11<0.15,>=0.13 in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from httpcore==1.*->httpx) (0.14.0)
Requirement already satisfied: exceptiongroup>=1.0.2 in /home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages (from anyio->httpx) (1.1.3)
Downloading httpx-0.27.0-py3-none-any.whl (75 kB)
   ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 75.6/75.6 kB 1.8 MB/s eta 0:00:00
Installing collected packages: httpx
  Attempting uninstall: httpx
    Found existing installation: httpx 0.25.1
    Uninstalling httpx-0.25.1:
      Successfully uninstalled httpx-0.25.1
Successfully installed httpx-0.27.0

[yarikoptic]

I think stuckness is resolved with the upgrade, thanks!