Reduce logging from intermediate CLI scripts by setting -v 0 in main() calls

[joshuacwnewton]

Description

Context

In many places in SCT's codebase, a CLI script (e.g. sct_label_vertebrae) will call another CLI script (e.g. sct_straighten_spinalcord).

Historically, the secondary CLI script will be called using a subprocess (via the run_proc function). Over the past year, however, SCT has migrated from using run_proc("sct_script") to import sct_script; sct_script.main().

Problem

While there have been benefits to this change, one unintended outcome of this change has been an increase in logging:

• run_proc is quiet; it prints only the command that was run, but outputs nothing else by default.
• sct_script.main() is noisy; it outputs everything exactly as it would if the CLI script was run from the terminal.

As a result, the logs for a CLI script now include additional nested logs for any intermediate CLI scripts called, too.

This problem is partially highlighted in #3877, but beyond display_viewer_syntax, any printv commands will be included in the output, too.

Solution

To fix this problem, this PR:

1. Ensures that -v 0 is set for every intermediate sct_script.main() call.
2. Ensures that this verbose setting propagates to any corresponding display_viewer_syntax() calls, too.

Caveats

The main caveat with setting -v 0 for intermediate calls is that SCT is not consistent with how it propagates arguments.v (i.e. verbose) to printv.

There are 272 instances of printv with verbose:

Compared to 215 instances of printv without verbose:

Meaning that -v 0 will silence some, but not all output from intermediate scripts.

For this reason, it might be better to leave -v and printv alone, temporarily accept the increased printv output, and instead focus solely on display_viewer_syntax, as per #3877 (comment).

Linked issues

Fixes #3877.

[mguaypaq]

Thank you for this large undertaking!

Could you also make verbose a non-optional argument of display_viewer_syntax() while you're at it? (That is, removing the default value in the function signature?) That would be a kind of automated test to make sure we don't introduce verbose-less calls in the future.

I agree that fixing printv verbosity is an even larger undertaking, and doesn't need to happen in this PR, which is a well-scoped improvement.

[joshuacwnewton]

Could you also make verbose a non-optional argument of display_viewer_syntax() while you're at it? (That is, removing the default value in the function signature?) That would be a kind of automated test to make sure we don't introduce verbose-less calls in the future.

Good call! This caught one instance of a verbose-less call in test_utils (which isn't super relevant, as it's not user-facing, but still demonstrative of your point!).

[joshuacwnewton]

This caught one instance of a verbose-less call

Ah! It looks like it did more than just catch 1 verbose-less call:

 Traceback (most recent call last):
  File "/__w/spinalcordtoolbox/spinalcordtoolbox/testing/cli/test_cli_sct_dmri_denoise_patch2self.py", line 88, in test_sct_dmri_denoise_patch2self
    '-o', fname_out, '-v', '2'])
  File "/__w/spinalcordtoolbox/spinalcordtoolbox/spinalcordtoolbox/scripts/sct_dmri_denoise_patch2self.py", line 140, in main
    display_viewer_syntax([file_to_denoise, output_file_name_denoised, output_file_name_diff])
TypeError: display_viewer_syntax() missing 1 required positional argument: 'verbose'

Sorry about that! I was sure I had run pytest prior to pushing, and these test failures didn't come up?

Either way, I'll take a closer look at the display_viewer_syntax calls. :)

[joshuacwnewton]

Just as one last sanity check here, I was hoping to compare the output of batch_processing.sh before and after these changes. ((batch_processing.sh represents a real-world processing pipeline, and so it contains the full, unfiltered output of many SCT scripts chained together.))

The trouble is, there are no image viewers (e.g. fsleyes) installed on the GitHub CI runners. So, the display_viewer_syntax output isn't present at all in either case!

---

Still, we can at least use this diff to see the effect that this PR has on non- display_viewer_syntax output (i.e. printv, etc.), which is something I was worried about (see "Caveats" in #3881 (comment)).

• Computed diff: There are 400 fewer lines, and luckily, the majority of them seem to all come from intermediate calls to sct_apply_transfo:

This is an acceptable (perhaps even welcome) change to me. The intermediate logging from sct_apply_transfo feels like it was cluttering the logs unnecessarily, and I think I'm happy to see it gone.

I'm also pleased to see that the changes from this PR have a (relatively) insignificant effect on CLI script logging, meaning that users aren't going to see wildly reduced output from their scripts. Things will be more or less business as usual, sans the (unwanted) display_viewer_syntax output. 😃

[joshuacwnewton]

If the above looks good to you, @mguaypaq, feel free to merge!