Output From Failed `subprocess.run` Calls Not Captured

[ericspod]

Describe the bug
In a few places such as here subprocess.run is called without any checks that a non-zero result was returned. In these situations the stdout/stderr from the call is lost and so doesn't appear in the output logs when CI/CD tests are run. It's difficult to reproduce the environment the test is run under so having this output is important for debugging when PR tests fail.

The solution is to use subprocess.run with capture_output=True and stderr=subprocess.STDOUT so that the raise exception will have that information. The exception should perhaps be caught and the output value it stores printed to stderr before being reraised. Other places where run or Popen are used might need modification as well.

[ericspod]

@myron @mingxin-zheng I think this is code that you've been involved in developing? This is related to an issue we're having with tests in #6257 I believe.

[mingxin-zheng]

Hi @ericspod , capture_output=True was firstly introduced and then changed in #5523 . These subprocess calls are for network training, which takes a long time to run. When capture_output was set to true, the outputs/prints from the subprocess are only displayed after completion, and so users complained they can't see any progress for hours.

[ericspod]

@mingxin-zheng I see, that could be a real bad thing for users. How long do the tests run? Perhaps we need some way of setting the capture on for tests only. Thanks!

[mingxin-zheng]

@ericspod That's a good idea. The tests run pretty fast usually. I think it is less than 3 minutes for each related unit test. The integration tests could take a bit longer but it is no more than 10 minutes.

[ericspod]

Hi @mingxin-zheng One of the tests that fails is this one so maybe adding a flag to run_algo to do capture would fix the issue for us. Also study.optimize has a similar error. These might be minor issues with the state of the CI/CD and something that'll be fixed in time but I can't tell without output.

[mingxin-zheng]

One implementation I have in mind now is to use the MONAI_DEBUG env var:

MONAI/monai/utils/misc.py

Line 519 in d23221f

def debug() -> bool:

Like other Auto3DSeg trainings, the chain of calls for run_algo is:
run_algo - train - _run_cmd - subprocess.run

In my mind, it would be something like this in _run_cmd:

if not MONAIEnvVars.debug():
    return subprocess.run(cmd_list, env=ps_environ, check=True)
else:
    try:
        return subprocess.run(cmd.split(), env=ps_environ, check=True, capture_output=True)
    except subprocess.CalledProcessError as e:
        output = repr(e.stdout).replace("\\n", "\n").replace("\\t", "\t")
        errors = repr(e.stderr).replace("\\n", "\n").replace("\\t", "\t")
        raise RuntimeError(f"subprocess call error {e.returncode}: {errors}, {output}")

If this satisfy the need in this ticket @ericspod @myron @wyli , I can move forward to create a PR.

[ericspod]

Let's put this into a separate utility function we can use in multiple places in the general case. This allows setting capture_output explicitly if desired but will override it with the debug status from the variable:

def run_cmd(cmd_list, **kwargs):
    debug = MONAIEnvVars.debug()
    kwargs["capture_output"] = kwargs.get("capture_output", debug)

    try:
        return subprocess.check_call(cmd_list, **kwargs)
    except subprocess.CalledProcessError as e:
        if not debug:
            raise
        output = repr(e.stdout).replace("\\n", "\n").replace("\\t", "\t")
        errors = repr(e.stderr).replace("\\n", "\n").replace("\\t", "\t")
        raise RuntimeError(f"subprocess call error {e.returncode}: {errors}, {output}")

[mingxin-zheng]

Thanks @ericspod . I started a PR for the discussed solution. There were quite many changes and tests for 1.2 release. Since this is mostly for debugging purposes, I did not work on it until now.

[ericspod]

Hi @mingxin-zheng Looking into this would be great thanks. We were able to sort the CICD issues relating to this for the PRs we had for 1.2 but it would be great to improve this now.