Quieter defaults for read.output

[infotroph]

Initially discussed in #3970, moving here for more planning before implementation: PEcAn.utils::read.output is very chatty by default, issuing lots of messages about routine behavior that get repeated as it handles each file even when reading a directory of thousands.

I propose the default behavior should be:

• print_summary = FALSE
• verbose = FALSE, as currently
• verbose = FALSE should additionally suppress all messages that are reporting documented behavior that it's safe to assume is what the user intended:
  • "missing [start/end] year"
  • "No start or end year provided"
  • "Reading the following files"
  • "Variables not specified. Reading output for all variables"
• These messages indicate directory contents that might not be what the user expected, so I can see a case for displaying them even when verbose = FALSE:
  • "netCDF files for other years present"
  • "No files found. Returning all NA"

In #3970 I had proposed approximating this by adding

if (!isTRUE(verbose)) {
    loglevel <- PEcAn.logger::logger.setLevel("WARN")
    on.exit(PEcAn.logger::logger.setLevel(loglevel), add = TRUE)
  }

to the top of the function so that all the DEBUG and INFO messages are suppressed by default, but there are at least three reasons that's not by itself a full solution:

1. The print_summary output is implemented as a logger.info call, so it would make print_summary only work in verbose mode.
2. Most of the debug messages are already written as if (!verbose) PEcAn.logger::logger.debug(...), so suppressing the other ones via logger levels creates a needless inconsistency.
3. Many of the read.output unit tests rely on checking for the messages I'm proposing to suppress. @divine7022 pointed out that we could add verbose=TRUE to those tests as a quick workaround, but I submit the tests ought to be rewritten to check the return value (which is what matters most!) instead of the messages.

[S1DDHEY]

A few alternatives that I feel could be worth considering:

1. Return metadata as attributes instead of printing it.
   Rather than logging Variables not specified ...., attaching the info to return, something like

attr(result, "files_read")    <- ncfiles
attr(result, "years_found")   <- nc_years
attr(result, "variables_read") <- variables

Zero noise by default, but the info is there for callers who want it, and it's machine-readable. This would also make the test problem disappear naturally.

2. replace verbose with a log_level parameter.
   Instead of manually gating individual messages behind if (verbose), the function could accept a log_level = "WARN" parameter and call logger.setLevel() at the top.

3. Extracting something like find_output_files() as a standalone function.

[S1DDHEY]

2. replace verbose with a log_level parameter.

Just realized a downside to this approach, If the function is called in a tight loop and an error interrupts before on.exit restores the level, the global level would stay changed for the rest of the session. This would be hard to debug.

[infotroph]

Return metadata as attributes instead of printing it

replace verbose with a log_level parameter

I think that's going the opposite direction from what I was picturing. My claim[*] is that these messages are basically all reporting a successful read with no user action needed, so it's safe to discard them entirely when not in verbose mode.

For context, my philosophy on console messages is that:

• Feedback on routine operations should be minimal, so that human readers will notice messages about cases where the function wasn't able to do what they requested, without those getting lost in output that amounts to "Doing what you asked, boss!"
• Having verbose mode turn on all the messages at once is a familiar pattern, and when debugging a single function I don't usually know at the outset which messages will matter. So I don't see a need for verbosity settings more granular than verbose/not verbose.

Applying that read.output, I think that when a user writes read.output(outdir = "some/path", variables = NULL, verbose = FALSE) we should interpret it as "Please read all the variables in all the netcdfs in this directory and don't bother me about the details."

[*] Which others might disagree with, that's why we're discussing here!

[S1DDHEY]

Ahh now I get, thanks for the explanation.

The print_summary output is implemented as a logger.info call, so it would make print_summary only work in verbose mode.

Can we not use message() instead of logger.info for print_summary? This would be completely independent of the log level.

Most of the debug messages are already written as if (!verbose) PEcAn.logger::logger.debug(...), so suppressing the other ones via logger levels creates a needless inconsistency.

For this case can we not just remove if (verbose) guard from the debug messages ? (currently used only for 2 debug messages in read.output)
Assuming that your approach of loglevel is implemented

[codewithchotu]

Hi! I'm a new contributor interested in helping with this issue.

I've been reading through the discussion and trying to understand the current behavior of read.output and the proposed approaches around logging and message suppression.

I'd be happy to investigate the code and explore potential implementation options. Before I start, would you recommend that a new contributor take on this issue, or are there smaller issues that would be better for getting familiar with the codebase first?

Thank you!