Bugs related to logger

[abhaasgoyal]

As of now, the logger is not being used properly in the codebase / has existing bugs.

Current issues

• render_job_script in pbs.py has verbose as a parameter, which would currently always be false. See Add payu test suite for spatial configuration #136 (comment) for the appropriate steps.
• subprocess.py is currently using print, when it should either be using logger / printing the command during the subprocess itself / other solutions. See DRAFT: Redesign test_subprocess logic #253 (comment) for a potential solution (which prints the command within subprocess.py using set -ex. A better method could be printing the command in the logger only. While implementing the solution, the corresponding tests could use caplog instead of capturing from capfd (they only check for file descriptors 1 and 2 and not the output from logger by default)
• Running benchcab without -v is still providing DEBUG log output. #280

[bschroeter]

OK, to provide some additional context here, I think we need to take a look at the code that redirects printing to standard out in subprocess.py.

benchcab/benchcab/utils/subprocess.py

Lines 60 to 80 in 9482458

	-------
	subprocess.CompletedProcess
	_description_
	"""
	# Use the logging level (10 = Debug) to determine verbosity.
	verbose = get_logger().getEffectiveLevel() == DEBUG_LEVEL
	kwargs: Any = {}
	with contextlib.ExitStack() as stack:
	if capture_output:
	kwargs["text"] = True
	kwargs["stdout"] = subprocess.PIPE
	elif output_file:
	kwargs["stdout"] = stack.enter_context(
	output_file.open("w", encoding="utf-8")
	)
	else:
	kwargs["stdout"] = None if verbose else subprocess.DEVNULL
	kwargs["stderr"] = subprocess.STDOUT
	if env:

I think that we can basically remove the bits that do the standard out catches of print statements and fall back onto using the native subprocess functionality to capture output from commands.

Now that I have a better understanding of this issue, prefixing set -x && to the command is not the correct approach, particularly if we are doing a log.debug() immediately prior. We should be relying on the logger to output commands in verbose mode, and leave the subprocess module to do its thing. We get no additional benefit by printing out the statement inside the subprocess call.

@SeanBryan51 can probably provide additional context here, as I believe he is most suited to comment being the author of this chunk of code.

With these comments added, I am going to un-assign myself as I am working on other tasks and I'm not sure when I'll be available to work on this one - particularly if it becomes a blocker. @ccarouge, please feel free to re-assign me if needed. It isn't a great deal of work to address this issue.

[SeanBryan51]

I think the redirection of subprocess output to stdout was done so that buffering the output wasn't required (this lets us see the output of subprocess commands in real time):

benchcab/benchcab/utils/subprocess.py

Line 77 in 9482458

kwargs["stdout"] = None if verbose else subprocess.DEVNULL

If the intention is to redirect the subprocess output to the logger, this SO post might be relevant: https://stackoverflow.com/questions/21953835/run-subprocess-and-print-output-to-logging

I'm not too sure exactly what the context is for this issue so I'm not sure if this helps, @abhaasgoyal can you update the issue description?

[abhaasgoyal]

@SeanBryan51 I have added the description for the issue. Let me know if anything's unclear.