000341 - trying to `git rm` non-existing file

yarikoptic commented 1 year ago

(base) dandi@drogon:/mnt/backup/dandi/dandisets$ flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron.lock bash -c '/mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify 000341'
Specified filename /mnt/backup/dandi/dandisets/000341/.git/index.lock does not exist.
2022-11-22T08:53:08-0500 [ERROR   ] backups2datalad: Job failed on input <Dandiset 000341/draft>:
Traceback (most recent call last):
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/asyncer.py", line 500, 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 660, in __aexit__
    raise ExceptionGroup(exceptions)
anyio._backends._asyncio.ExceptionGroup: 2 exceptions were raised in the task group:
----------------------------
Traceback (most recent call last):
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/adataset.py", line 218, in remove
    await self.call_git(
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/adataset.py", line 117, in call_git
    await aruncmd("git", *args, cwd=self.path, **kwargs)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/aioutil.py", line 204, in aruncmd
    return await anyio.run_process(argstrs, **kwargs)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_core/_subprocesses.py", line 90, in run_process
    raise CalledProcessError(cast(int, process.returncode), command, output, errors)
subprocess.CalledProcessError: Command '['git', 'rm', '-f', '--ignore-unmatch', '--', 'In_vitro_oscillation_Rat/sub-1807302tm/sub-1807302tm_ses-1807302tm-3-1,2,4-1_icephys.nwb']' returned non-zero exit status 128.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/asyncer.py", line 263, in process_asset
    await self.ds.remove(asset.path)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/adataset.py", line 230, in remove
    r = await aruncmd("fuser", "-v", lockfile, stdout=subprocess.PIPE)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/aioutil.py", line 204, in aruncmd
    return await anyio.run_process(argstrs, **kwargs)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_core/_subprocesses.py", line 90, in run_process
    raise CalledProcessError(cast(int, process.returncode), command, output, errors)
subprocess.CalledProcessError: Command '['fuser', '-v', '/mnt/backup/dandi/dandisets/000341/.git/index.lock']' returned non-zero exit status 1.
----------------------------
Traceback (most recent call last):
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_core/_subprocesses.py", line 83, in run_process
    await process.wait()
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 662, in __aexit__
    raise exceptions[0]
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 733, in task_done
    exc = _task.exception()
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/asyncer.py", line 263, in process_asset
    await self.ds.remove(asset.path)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/adataset.py", line 218, in remove
    await self.call_git(
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/adataset.py", line 117, in call_git
    await aruncmd("git", *args, cwd=self.path, **kwargs)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/aioutil.py", line 204, in aruncmd
    return await anyio.run_process(argstrs, **kwargs)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_core/_subprocesses.py", line 85, in run_process
    process.kill()
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 1056, in kill
    self._process.kill()
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/asyncio/subprocess.py", line 144, in kill
    self._transport.kill()
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/asyncio/base_subprocess.py", line 153, in kill
    self._check_proc()
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/asyncio/base_subprocess.py", line 142, in _check_proc
    raise ProcessLookupError()
ProcessLookupError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/aioutil.py", line 170, in dowork
    outp = await func(inp)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/datasetter.py", line 145, in update_dandiset
    changed = await self.sync_dataset(dandiset, ds, dmanager)
  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 500, in async_assets
    nursery.start_soon(dm.read_addurl)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/httpx/_client.py", line 1975, in __aexit__
    await self._transport.__aexit__(exc_type, exc_value, traceback)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/httpx/_transports/default.py", line 332, in __aexit__
    await self._pool.__aexit__(exc_type, exc_value, traceback)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/httpcore/_async/connection_pool.py", line 326, in __aexit__
    await self.aclose()
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/httpcore/_async/connection_pool.py", line 312, in aclose
    raise RuntimeError(
RuntimeError: The connection pool was closed while 6 HTTP requests/responses were still in-flight.
Traceback (most recent call last):
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/runpy.py", line 194, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/__main__.py", line 499, in <module>
    main(_anyio_backend="asyncio")
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/asyncclick/core.py", line 1157, in __call__
    return anyio.run(self._main, main, args, kwargs, **opts)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_core/_eventloop.py", line 70, in run
    return asynclib.run(func, *args, **backend_options)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 292, in run
    return native_run(wrapper(), debug=debug)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 287, in wrapper
    return await func(*args)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/asyncclick/core.py", line 1160, in _main
    return await main(*args, **kwargs)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/asyncclick/core.py", line 1076, in main
    rv = await self.invoke(ctx)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/asyncclick/core.py", line 1687, in invoke
    return await _process_result(await sub_ctx.command.invoke(sub_ctx))
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/asyncclick/core.py", line 1434, in invoke
    return await ctx.invoke(self.callback, **ctx.params)
  File "/home/dandi/miniconda3/envs/dandisets/lib/python3.8/site-packages/asyncclick/core.py", line 780, in invoke
    rv = await rv
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/__main__.py", line 185, in update_from_backup
    await datasetter.update_from_backup(dandisets, exclude=exclude)
  File "/mnt/backup/dandi/dandisets/tools/backups2datalad/datasetter.py", line 97, in update_from_backup
    raise RuntimeError(
RuntimeError: Backups for 1 Dandiset failed

fuser shouldn't be called if index file is not even there

process seems to try to git rm file which isn't there


(base) dandi@drogon:/mnt/backup/dandi/dandisets/000341$ ls -l 'In_vitro_oscillation_Rat/sub-1608041tm/sub-1608041tm_ses-1608041tm-3-5,17-4_icephys.nwb'
ls: cannot access 'In_vitro_oscillation_Rat/sub-1608041tm/sub-1608041tm_ses-1608041tm-3-5,17-4_icephys.nwb': No such file or directory
(base) dandi@drogon:/mnt/backup/dandi/dandisets/000341$ ls -l 'In_vitro_oscillation_Rat/sub-1608041tm/'
total 0
(base) dandi@drogon:/mnt/backup/dandi/dandisets/000341$ git status
On branch draft
Your branch is up to date with 'github/draft'.

nothing to commit, working tree clean



not clear how that happened -- but I don't see any "manual" commit in `git log` so must have come to this state programmatically.  I have bounced you @jwodder all emails which mention that 000341 .

jwodder commented 1 year ago

@yarikoptic

process seems to try to git rm file which isn't there

The code always removes an asset that needs to be updated before updating it. If the asset doesn't exist, the --ignore-unmatch option should mean that git rm does nothing and exits successfully.

jwodder commented 1 year ago

@yarikoptic The asset in question is now present in the 000341 backup.

yarikoptic commented 1 year ago

@yarikoptic

process seems to try to git rm file which isn't there

The code always removes an asset that needs to be updated before updating it. If the asset doesn't exist, the --ignore-unmatch option should mean that git rm does nothing and exits successfully.

ah, right, but then why it actually "returned non-zero exit status 128" ?

@yarikoptic The asset in question is now present in the 000341 backup.

cool, but how did you get there? why my invocation didn't?

jwodder commented 1 year ago

@yarikoptic

ah, right, but then why it actually "returned non-zero exit status 128" ?

Because the repo was locked.

cool, but how did you get there? why my invocation didn't?

I didn't do anything. The backup was automatically updated by the time I got to it.

yarikoptic commented 1 year ago

ah, right, but then why it actually "returned non-zero exit status 128" ?

Because the repo was locked.

locked by what if lock file didn't exist?

I didn't do anything. The backup was automatically updated by the time I got to it.

ah, ok.

jwodder commented 1 year ago

@yarikoptic

locked by what if lock file didn't exist?

I don't know, but it's possible that the lock was undone before fuser ran.

yarikoptic commented 1 year ago

ok, so the mystery will remain on why it crashed to start with -- hypothetically what processes managed to lock it which lead to error

dandi / dandisets

000341 - trying to `git rm` non-existing file #306