con / duct

A helper to run a command, capture stdout/stderr and details about running
https://pypi.org/project/con-duct/
MIT License
3 stars 2 forks source link

Might provide summary interleaved with command stderr #203

Open yarikoptic opened 1 month ago

yarikoptic commented 1 month ago

while running duct with backups2datalad:

duct flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron-nonzarr.lock bash -c '/mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify'

I got it ending with

    | +    wasAssociatedWith:
    | +    - identifier: RRID:SCR_019009
    | +      name: DANDI Command Line Interface
    | +      schemaKey: Software
    | +      url: https://github.com/dandi/dandi-cli
    | +      version: 0.62.3
    | +  - description: Metadata generated by DANDI cli
    | +    endDate: '2024-07-15T11:44:33.410278-04:00'
    | +    id: urn:uuid:ffcdc7de-8271-4f61-8792-dafc88f95f1b
    | +    name: Metadata generation
    | +    schemaKey: Activity
    | +    startDate: '2024-07-15T11:44:33.410278Exit Code: 1
Command: flock -E 0 -e -n /home/dandi/.run/backup2datalad-cron-nonzarr.lock bash -c /mnt/backup/dandi/dandisets/tools/backups2datalad-update-cron --mode verify
Log files location: .duct/logs/2024.10.10T17.41.45-2122745_
Wall Clock Time: 1376.580 sec sec
Memory Peak Usage (RSS): 749872 KiB
Memory Average Usage (RSS): 539041.119 KiB
Virtual Memory Peak Usage (VSZ): 2149780532 KiB
Virtual Memory Average Usage (VSZ): 987381566.521 KiB
Memory Peak Percentage: 0.7999999999999999%
Memory Average Percentage: 0.595%
CPU Peak Usage: 117.7%
Average CPU Usage: 34.458%
Samples Collected: 1022
Reports Written: 23

-04:00'
    | +    wasAssociatedWith:
    | +    - identifier: RRID:SCR_019009
    | +      name: DANDI Command Line Interface
    | +      schemaKey: Software
    | +      url: https://github.com/dandi/dandi-cli
    | +      version: 0.62.3
    | +modified: '2024-07-15T15:44:33.685958Z'
    | +path: rawdata/dataset_description.json
    | +size: 364
    |
    |
    +------------------------------------
2024-10-10T18:04:13-0400 [ERROR   ] backups2datalad: Job failed on input <Dandiset 001089/draft>:
Traceback (most recent call last):
  File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/backups2datalad/aioutil.py", line 177, in dowork
    outp = await func(inp)
  File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/backups2datalad/datasetter.py", line 200, in update_dandiset
    changed = await self.sync_dataset(
  File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/backups2datalad/datasetter.py", line 233, in sync_dataset
    raise RuntimeError(f"Dirty {dandiset}; clean or save before running")
RuntimeError: Dirty Dandiset 001089/draft; clean or save before running
2024-10-10T18:04:41-0400 [ERROR   ] backups2datalad: An error occurred:
Traceback (most recent call last):
  File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/backups2datalad/__main__.py", line 119, in wrapped
    await f(datasetter, *args, **kwargs)
  File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/backups2datalad/__main__.py", line 229, in update_from_backup
    await datasetter.update_from_backup(dandisets, exclude=exclude)
  File "/home/dandi/miniconda3/envs/dandisets-2/lib/python3.10/site-packages/backups2datalad/datasetter.py", line 135, in update_from_backup
    raise RuntimeError(
RuntimeError: Backups for 3 Dandisets failed
Logs saved to /mnt/backup/dandi/dandisets/.git/dandi/backups2datalad/2024.10.10.21.41.56Z.log
action summary:
  publish (notneeded: 2)
publish(ok): . (dataset) [refs/heads/draft->github:refs/heads/draft e2847c5..b29bf2c]
publish(ok): . (dataset) [refs/heads/git-annex->github:refs/heads/git-annex 5c74fa8..9c08100]
action summary:
  publish (ok: 2)
publish(ok): . (dataset) [refs/heads/draft->github:refs/heads/draft 9aeed6f..f9675c6]
publish(ok): . (dataset) [refs/heads/git-annex->github:refs/heads/git-annex a968fc0..50576a0]
action summary:
  publish (ok: 2)

I really do not think we are detaching within child process but I could be shown wrong. It is an async python app, so may be it has something to do with that.

The resultant files were

(dandisets-2) dandi@drogon:/mnt/backup/dandi/dandisets$ ls -ld .duct/logs/2024.10.10T17.41.45-2122745_*
-rw-r--r-- 1 dandi dandi   861 Oct 10 18:04 .duct/logs/2024.10.10T17.41.45-2122745_info.json
-rw-r--r-- 1 dandi dandi     0 Oct 10 17:41 .duct/logs/2024.10.10T17.41.45-2122745_stderr
-rw-r--r-- 1 dandi dandi 39272 Oct 10 18:04 .duct/logs/2024.10.10T17.41.45-2122745_stdout
-rw-r--r-- 1 dandi dandi 48493 Oct 10 18:04 .duct/logs/2024.10.10T17.41.45-2122745_usage.json

so no stderr , and stdout containing aforementioned output which was interleaved. So it seems just a matter of interleaving duct's logging stderr and underlying process stdout which somehow was not flushed.

Could we flush stdout of the underlying process somehow upon completion? may be simply calling sys.stdout.flush() and the same for stderr would address this although not sure it it would have a desired effect. I will keep an eye if issue is reproducible.