Feature 685 log updates

[georgemccabe]

These changes include updates to improve the readability of logging for users. It also makes it easier for developers to review test output.

Change Summary

Log Output (users)

• LOG_LEVEL_TERMINAL METplus config variable was added to control the level of logs that are output to the terminal screen separately from the log file level.
• If LOG_LEVEL_TERMINAL is set so that INFO logs are not output to the screen, then important info like the METplus version, command used and message that METplus finished running are still printed to the screen.
• Cleaned up logging output
  • METplus configuration steps are printed instead of run through the logger. This output is only sent to the screen because they are run before the log file is initialized, but it was difficult to tell them apart from the info that is actually included in the log file.
  • If logs are not written to a log file (LOG_METPLUS is empty), then output a more useful message to alert users
  • Changed level of logs that output environment variable values to DEBUG from INFO so that INFO log output is more concise and only includes info like wrapper that is being run, init/valid time, forecast lead processed, and commands that are run.
  • Changed log that reports length of time taken to run application to INFO

Automated Tests (internal)

• Added log grouping (collapsible sections) for GitHub Actions log output so it is much easier to navigate.
  • Group output from commands that are run and timing information, error messages are not grouped so they can be easily spotted
  • Group full difference test output so it is easier to navigate to diff summary
• Added python function used to call commands in GHA so that all commands are called consistently with error reporting, timing information, and GHA log grouping
• Refactored Docker calls for running METplus use cases so they can be reviewed more easily
  • Previously a single docker run command was called to run all environment setup shell commands and all use cases for a given use case group. This resulted in a large mess of log output from all cases that was difficult to navigate.
  • Now a docker run command is run to start a container running in the background and commands are executed in container using docker exec.
  • Setup steps are run in via docker exec to obtain additional components like METplotpy/METcalcpy/METdataio. Instead of exporting environment variables to set the PATH, the export commands are appended to the /etc/bashrc file so subsequent docker exec calls that use bash -l to create a login shell will contain the correct environment to run the use cases.
  • Each use case call to run_metplus.py is run in its own docker exec command so that it is clear in the logs which use cases failed. The screen log output is at INFO level and log file is at DEBUG level so GHA logs are easier to navigate but log files with DEBUG logs can be downloaded from artifacts and reviewed if needed.

Pull Request Testing

• Describe testing already performed for these changes:
  

Triggered GHA runs and confirmed that everything ran as expected and log output is more digestible

• Recommend testing for the reviewer(s) to perform, including the location of input datasets, and any additional instructions:
  

• Review GitHub Actions logs under "Run Use Cases" and "Run difference tests" for a few use case runs and compare to previous format

Examples:
Run Use Cases old format: https://github.com/dtcenter/METplus/actions/runs/3661208424/jobs/6189214533#step:7:1
Run Use Cases new format: https://github.com/dtcenter/METplus/actions/runs/3715930398/jobs/6301696050#step:7:1

Run difference tests old format: https://github.com/dtcenter/METplus/actions/runs/3661208424/jobs/6189214533#step:9:1
Run difference tests new format: https://github.com/dtcenter/METplus/actions/runs/3715930398/jobs/6301696050#step:9:1

• Review GHA run that includes a deliberate failure of a use case to see how error messages and other log output are now formatted: Here is an example

• Review after adding the summary of use cases that error at the bottom of the "Run Use Cases" GHA log output
  Navigate to this workflow run and click on "Use Case Tests: met_tool_wrapper..." You should see a summary of the use cases that failed at the bottom of the "Run Use Cases" section that automatically pops up.

• Checkout feature_685_log_updates branch run some tests:

  • Run a use case, review new log output format compared to develop
  • Play with LOG_LEVEL and LOG_LEVEL_TERMINAL variables to confirm they work as expected

• Do these changes include sufficient documentation updates, ensuring that no errors or warnings exist in the build of the documentation? [Yes]

• Do these changes include sufficient testing updates? [Yes]

• Will this PR result in changes to the test suite? [No]
  
  The log format will changes but there should be no differences in the test results

• Please complete this pull request review by 12/23/2022.
  

Pull Request Checklist

See the METplus Workflow for details.

• Add any new Python packages to the METplus Components Python Requirements table.
• Review the source issue metadata (required labels, projects, and milestone).
• Complete the PR definition above.
• Ensure the PR title matches the feature or bugfix branch name.
• Define the PR metadata, as permissions allow.
  Select: Reviewer(s)
  Select: Organization level software support Project or Repository level development cycle Project
  Select: Milestone as the version that will include these changes
• After submitting the PR, select Development issue with the original issue number.
• After the PR is approved, merge your changes. If permissions do not allow this, request that the reviewer do the merge.
• Close the linked issue and delete your feature or bugfix branch from GitHub.

[georgemccabe]

Temporarily closing this PR to make an additional enhancement, then reopening for review.

[JohnHalleyGotway]

I approve of these changes.

I reviewed the updated logging output from GHA and really prefer the improved formatting! Being able to set the log level for the log file versus the screen is great. I see that the docs have been updated accordingly.

I see that they pytest terminal logging is now set to WARNING which makes sense. Warning/Errors are printed to the terminal while the log file contains the details.

Changing GHA to docker exec each use case in a running container makes the logs much easier to navigate.

I scrolled through the actual code changes but not in an exhaustive way. I don't have any changes to recommend there.

[j-opatz]

Reviewed branch changes and appreciate the new screen log settings. The ability to differ verbosity levels between log files and screen logs will no doubt be very useful for users. Update for GHA errors also looks clean and should help troubleshooting.
I approve this PR