From c5e910dc2304c6c5dcfe35406b6efa64e38b9d9c Mon Sep 17 00:00:00 2001 From: George McCabe <23407799+georgemccabe@users.noreply.github.com> Date: Wed, 1 Nov 2023 16:43:57 -0600 Subject: [PATCH] Feature #2377 Log to terminal only (#2398) --- .github/workflows/testing.yml | 4 +- docs/Users_Guide/glossary.rst | 10 +- docs/Users_Guide/release-notes.rst | 14 ++ docs/Users_Guide/systemconfiguration.rst | 13 ++ internal/tests/pytests/conftest.py | 2 +- .../config_metplus/test_config_metplus.py | 27 ++- .../pytests/util/run_util/test_run_util.py | 57 +++++- .../string_manip/test_util_string_manip.py | 56 +++++- .../command_builder/test_command_builder.py | 5 +- .../wrappers/pb2nc/test_pb2nc_wrapper.py | 2 +- metplus/util/config_metplus.py | 49 ++--- metplus/util/run_util.py | 113 ++++++++++- metplus/util/string_manip.py | 29 +++ metplus/util/string_template_substitution.py | 2 +- metplus/wrappers/command_builder.py | 41 ++-- metplus/wrappers/command_runner.py | 181 ------------------ parm/metplus_config/defaults.conf | 1 + 17 files changed, 362 insertions(+), 244 deletions(-) delete mode 100755 metplus/wrappers/command_runner.py diff --git a/.github/workflows/testing.yml b/.github/workflows/testing.yml index 239189fb1c..e08aac81e4 100644 --- a/.github/workflows/testing.yml +++ b/.github/workflows/testing.yml @@ -145,8 +145,10 @@ jobs: env: METPLUS_TEST_OUTPUT_BASE: ${{ runner.workspace }}/pytest_output - name: Generate coverage report - run: coverage report -m + run: | + coverage report -m --fail-under=90 || echo "::error file=coverage,line=1,col=1::Code coverage is below 90%" if: always() + continue-on-error: true - name: Run Coveralls uses: AndreMiras/coveralls-python-action@8799c9f4443ac4201d2e2f2c725d577174683b99 if: always() diff --git a/docs/Users_Guide/glossary.rst b/docs/Users_Guide/glossary.rst index 1373c9e059..ef14ea48bc 100644 --- a/docs/Users_Guide/glossary.rst +++ b/docs/Users_Guide/glossary.rst @@ -2289,7 +2289,15 @@ METplus Configuration Glossary LOG_METPLUS Path to the METplus log file. Control the timestamp appended to the filename with :term:`LOG_TIMESTAMP_TEMPLATE`. - Set this variable to an empty string to turn off all logging. + Set this variable to an empty string or set :term:`LOG_TO_TERMINAL_ONLY` + = True to turn off all file logging and write all logs to the screen. + + | *Used by:* All + + LOG_TO_TERMINAL_ONLY + Set to True to skip writing any log files and instead send all log output + to the screen. Sets :term:`LOG_METPLUS` to an empty string if True. + Defaults to False. | *Used by:* All diff --git a/docs/Users_Guide/release-notes.rst b/docs/Users_Guide/release-notes.rst index 0464c17526..c00627a35e 100644 --- a/docs/Users_Guide/release-notes.rst +++ b/docs/Users_Guide/release-notes.rst @@ -107,6 +107,20 @@ See :ref:`met-config-overrides` for more information. How to tell if upgrade is needed ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +If the wrapped MET config file used by a use case is the version provided +with the METplus wrappers, then no changes to the use case are needed. +The wrapped MET config files provided with the wrappers are found in the +parm/met_config directory. + +Search for variables that end with **_CONFIG_FILE** in the use case +configuration file. + +If the value looks like this:: + + GRID_STAT_CONFIG_FILE = {PARM_BASE}/met_config/GridStatConfig_wrapped + +or the variable it not found, then no changes are needed. + Prior to v6.0.0, a use case that uses a wrapped MET config file that is out-of-date from the version provided with the METplus wrappers will report a warning in the log output alerting the user that an expected environment diff --git a/docs/Users_Guide/systemconfiguration.rst b/docs/Users_Guide/systemconfiguration.rst index 15efdfbeef..bca6adb1db 100644 --- a/docs/Users_Guide/systemconfiguration.rst +++ b/docs/Users_Guide/systemconfiguration.rst @@ -340,6 +340,19 @@ to the METplus log file:: If set to false/no, the output is written to a separate file in the log directory named after the application. + +.. _log_to_terminal_only: + +LOG_TO_TERMINAL_ONLY +"""""""""""""""""""" + +If set to True, all log output is written to the screen only. +This includes output from commands that are run, e.g. MET commands. +No log files will be created and :ref:`log_metplus` will be set to an empty +string. :: + + LOG_TO_TERMINAL_ONLY = True + Log Level Information ^^^^^^^^^^^^^^^^^^^^^ diff --git a/internal/tests/pytests/conftest.py b/internal/tests/pytests/conftest.py index 299410036f..4e3f94c6bb 100644 --- a/internal/tests/pytests/conftest.py +++ b/internal/tests/pytests/conftest.py @@ -136,7 +136,7 @@ def read_configs(extra_configs): script_dir = os.path.dirname(__file__) minimum_conf = os.path.join(script_dir, "minimum_pytest.conf") args = extra_configs.copy() - args.append(minimum_conf) + args.insert(0, minimum_conf) config = config_metplus.setup(args) return config diff --git a/internal/tests/pytests/util/config_metplus/test_config_metplus.py b/internal/tests/pytests/util/config_metplus/test_config_metplus.py index ca6daf44f6..657a0e8642 100644 --- a/internal/tests/pytests/util/config_metplus/test_config_metplus.py +++ b/internal/tests/pytests/util/config_metplus/test_config_metplus.py @@ -7,9 +7,34 @@ from datetime import datetime from metplus.util import config_metplus -from metplus.util.time_util import ti_calculate from metplus.util.config_validate import validate_config_variables + +@pytest.mark.parametrize( + 'config_overrides,expected_logfile', [ + (['config.LOG_METPLUS={LOG_DIR}/metplus.log'], '/metplus.log'), + (['config.LOG_METPLUS='], ''), + (['config.LOG_METPLUS={LOG_DIR}/metplus.log.{LOG_TIMESTAMP}', + 'config.LOG_TIMESTAMP_TEMPLATE=%Y'], '/metplus.log.'), + (['config.LOG_METPLUS={LOG_DIR}/metplus.log.{LOG_TIMESTAMP}', + 'config.LOG_TIMESTAMP_USE_DATATIME=True', 'config.LOOP_BY=INIT', + 'config.INIT_TIME_FMT=%Y', 'config.INIT_BEG=1987', + 'config.LOG_TIMESTAMP_TEMPLATE=%Y'], '/metplus.log.1987'), + (['config.LOG_METPLUS={LOG_DIR}/metplus.log', + 'config.LOG_TO_TERMINAL_ONLY=True'], ''), + (['config.LOG_TO_TERMINAL_ONLY=True'], ''), + (['config.LOG_METPLUS=metplus.log'], '/metplus.log'), + ] +) +@pytest.mark.util +def test_set_logvars(metplus_config_files, config_overrides, expected_logfile): + config = metplus_config_files(config_overrides) + log_dir = config.getdir('LOG_DIR') + expected = expected_logfile.replace('', log_dir) + expected = expected.replace('', datetime.now().strftime('%Y')) + assert config.getstr('config', 'LOG_METPLUS') == expected + + @pytest.mark.util def test_get_default_config_list(): test_data_dir = os.path.abspath(os.path.join(os.path.dirname(__file__), diff --git a/internal/tests/pytests/util/run_util/test_run_util.py b/internal/tests/pytests/util/run_util/test_run_util.py index 4b197d0d46..45d27fa46a 100644 --- a/internal/tests/pytests/util/run_util/test_run_util.py +++ b/internal/tests/pytests/util/run_util/test_run_util.py @@ -1,6 +1,9 @@ -import os import pytest from unittest import mock + +import os + +import produtil import metplus.util.run_util as ru import metplus.util.wrapper_init as wi from metplus.wrappers.ensemble_stat_wrapper import EnsembleStatWrapper @@ -40,6 +43,7 @@ 'CONFIG_INPUT', 'RUN_ID', 'LOG_TIMESTAMP', + 'LOG_TO_TERMINAL_ONLY', 'METPLUS_BASE', 'PARM_BASE', 'METPLUS_VERSION', @@ -61,6 +65,57 @@ def get_config_from_file(conf_file='run_util.conf'): conf_inputs = get_run_util_configs(conf_file) return ru.pre_run_setup(conf_inputs) +@pytest.mark.parametrize( + "log_met_to_metplus,copyable_env", + [ + (False, 'some text'), + (False, ''), + (True, 'some text'), + (True, ''), + ], +) +@pytest.mark.util +def test_log_header_info(tmp_path_factory, log_met_to_metplus, copyable_env): + fake_log = tmp_path_factory.mktemp("data") / 'fake.log' + cmd = '/my/cmd' + ru._log_header_info(fake_log, copyable_env=copyable_env, cmd=cmd, log_met_to_metplus=log_met_to_metplus) + with open(fake_log, 'r') as file_handle: + file_content = file_handle.read() + + assert 'OUTPUT:' in file_content + if not log_met_to_metplus: + assert "COMMAND" in file_content + assert cmd in file_content + if copyable_env: + assert copyable_env in file_content + + +@pytest.mark.parametrize( + "cmd,skip_run,use_log_path,expected_to_fail", + [ + (None, False, True, False), # no command + ('/my/cmd some args', True, True, False), # skip run + ('echo hello', False, True, False), # simple command with log + ('echo hello', False, False, False), # simple command no log + ('echo hello; echo hi', False, True, False), # complex 2 commands with log + ('echo hello; echo hi', False, False, False), # complex 2 commands no log + ('ls *', False, False, False), # complex command with wildcard * + ('ls fake_dir', False, False, True), # failed command + ], +) +@pytest.mark.util +def test_run_cmd(tmp_path_factory, cmd, skip_run, use_log_path, expected_to_fail): + log_path = str(tmp_path_factory.mktemp("data") / 'fake_run_cmd.log') if use_log_path else None + run_arguments = ru.RunArgs( + logger=None, + log_path=log_path, + skip_run=skip_run, + log_met_to_metplus=True, + env=os.environ, + copyable_env='some text', + ) + actual = ru.run_cmd(cmd, run_arguments) + assert bool(actual) == expected_to_fail @pytest.mark.util def test_pre_run_setup(): diff --git a/internal/tests/pytests/util/string_manip/test_util_string_manip.py b/internal/tests/pytests/util/string_manip/test_util_string_manip.py index 958d902b70..e448eb2ba0 100644 --- a/internal/tests/pytests/util/string_manip/test_util_string_manip.py +++ b/internal/tests/pytests/util/string_manip/test_util_string_manip.py @@ -3,10 +3,61 @@ import pytest import pprint -from csv import reader +from datetime import datetime from metplus.util.string_manip import * -from metplus.util.string_manip import _fix_list + + +@pytest.mark.parametrize( + 'config_overrides,logfile_arg,expected_logfile', [ + ({'LOG_METPLUS': ''}, None, None), + ({'LOG_METPLUS': '{LOG_DIR}/metplus.log'}, None, '/metplus.log'), + ({'LOG_METPLUS': '{LOG_DIR}/metplus.log', + 'LOG_MET_OUTPUT_TO_METPLUS': True}, 'app.log', '/metplus.log'), + ({'LOG_METPLUS': '{LOG_DIR}/metplus.log', + 'LOG_MET_OUTPUT_TO_METPLUS': False, + 'LOG_TIMESTAMP': ''}, 'app.log', '/app.log'), + ({'LOG_METPLUS': '{LOG_DIR}/metplus.log', + 'LOG_MET_OUTPUT_TO_METPLUS': False, + 'LOG_TIMESTAMP': '2020'}, 'app.log', '/app.log.2020'), + ] +) +@pytest.mark.util +def test_set_logvars(metplus_config, config_overrides, logfile_arg, expected_logfile): + config = metplus_config + for key, value in config_overrides.items(): + config.set('config', key, value) + + log_dir = config.getdir('LOG_DIR') + if expected_logfile is None: + expected = expected_logfile + else: + expected = expected_logfile.replace('', log_dir) + expected = expected.replace('', datetime.now().strftime('%Y')) + assert get_log_path(config, logfile=logfile_arg) == expected + + +@pytest.mark.parametrize( + 'config_overrides,expected_logfile', [ + ({'LOG_TO_TERMINAL_ONLY': True}, + 'Set LOG_TO_TERMINAL_ONLY=False to write logs to a file'), + ({'LOG_TO_TERMINAL_ONLY': False, + 'LOG_METPLUS': '{LOG_DIR}/metplus.log'}, + '/metplus.log'), + ({'LOG_TO_TERMINAL_ONLY': False, + 'LOG_METPLUS': ''}, + 'Set LOG_METPLUS to write logs to a file'), + ] +) +@pytest.mark.util +def test_get_logfile_info(metplus_config, config_overrides, expected_logfile): + config = metplus_config + for key, value in config_overrides.items(): + config.set('config', key, value) + log_dir = config.getdir('LOG_DIR') + expected = expected_logfile.replace('', log_dir) + assert get_logfile_info(config) == expected + @pytest.mark.parametrize( 'template, expected_output', [ @@ -21,6 +72,7 @@ def test_template_to_regex(template, expected_output): assert template_to_regex(template) == expected_output + @pytest.mark.parametrize( 'subset_definition, expected_result', [ ([1, 3, 5], ['b', 'd', 'f']), diff --git a/internal/tests/pytests/wrappers/command_builder/test_command_builder.py b/internal/tests/pytests/wrappers/command_builder/test_command_builder.py index 93a3bcb80a..89fd7fef36 100644 --- a/internal/tests/pytests/wrappers/command_builder/test_command_builder.py +++ b/internal/tests/pytests/wrappers/command_builder/test_command_builder.py @@ -7,6 +7,7 @@ import datetime import metplus.wrappers.command_builder as cb_wrapper from metplus.wrappers.command_builder import CommandBuilder +import metplus.util.run_util from metplus.util import ti_calculate, add_field_info_to_time_info @@ -145,7 +146,7 @@ def test_find_obs_offset(metplus_config, offsets, expected_file, offset_seconds) pcw.c_dict['OFFSETS'] = offsets pcw.c_dict['OBS_INPUT_DIR'] = get_data_dir(pcw.config) - pcw.c_dict['OBS_INPUT_TEMPLATE'] = "{da_init?fmt=%2H}z.prepbufr.tm{offset?fmt=%2H}.{da_init?fmt=%Y%m%d}" + pcw.c_dict['OBS_INPUT_TEMPLATE'] = "{da_init?fmt=%H}z.prepbufr.tm{offset?fmt=%2H}.{da_init?fmt=%Y%m%d}" add_field_info_to_time_info(time_info, var_info) obs_file, time_info = pcw.find_obs_offset(time_info) @@ -1097,7 +1098,7 @@ def test_run_command_error(metplus_config, log_metplus): config.set('config', 'LOG_METPLUS', '') cb = CommandBuilder(metplus_config) - with mock.patch.object(cb.cmdrunner, 'run_cmd', return_value=('ERR',None)): + with mock.patch.object(cb, 'run_cmd', return_value=-1): actual = cb.run_command('foo') assert not actual assert _in_last_err('Command returned a non-zero return code: foo', cb.logger) diff --git a/internal/tests/pytests/wrappers/pb2nc/test_pb2nc_wrapper.py b/internal/tests/pytests/wrappers/pb2nc/test_pb2nc_wrapper.py index 5e612e93ce..64bea4e074 100644 --- a/internal/tests/pytests/wrappers/pb2nc/test_pb2nc_wrapper.py +++ b/internal/tests/pytests/wrappers/pb2nc/test_pb2nc_wrapper.py @@ -255,7 +255,7 @@ def test_pb2nc_all_fields(metplus_config, config_overrides, '{PARM_BASE}/met_config/PB2NCConfig_wrapped') config.set('config', 'PB2NC_INPUT_DIR', input_dir) config.set('config', 'PB2NC_INPUT_TEMPLATE', - 'ndas.t{da_init?fmt=%2H}z.prepbufr.tm{offset?fmt=%2H}.{da_init?fmt=%Y%m%d}.nr') + 'ndas.t{da_init?fmt=%H}z.prepbufr.tm{offset?fmt=%2H}.{da_init?fmt=%Y%m%d}.nr') config.set('config', 'PB2NC_OUTPUT_DIR', '{OUTPUT_BASE}/PB2NC/output') config.set('config', 'PB2NC_OUTPUT_TEMPLATE', '{valid?fmt=%Y%m%d%H}.nc') diff --git a/metplus/util/config_metplus.py b/metplus/util/config_metplus.py index f898039818..c842f96840 100644 --- a/metplus/util/config_metplus.py +++ b/metplus/util/config_metplus.py @@ -291,19 +291,23 @@ def _set_logvars(config): # add LOG_TIMESTAMP to the final configuration file config.set('config', 'LOG_TIMESTAMP', log_filenametimestamp) - metplus_log = config.strinterp( - 'config', - '{LOG_METPLUS}', - LOG_TIMESTAMP_TEMPLATE=log_filenametimestamp - ) - - # add log directory to log file path if only filename was provided - if metplus_log: - if os.path.basename(metplus_log) == metplus_log: - metplus_log = os.path.join(config.getdir('LOG_DIR'), metplus_log) - print('Logging to %s' % metplus_log) + if config.getbool('config', 'LOG_TO_TERMINAL_ONLY'): + metplus_log = '' else: + metplus_log = config.strinterp( + 'config', + '{LOG_METPLUS}', + LOG_TIMESTAMP_TEMPLATE=log_filenametimestamp + ) + + # add log directory to log file path if only filename was provided + if metplus_log and os.path.basename(metplus_log) == metplus_log: + metplus_log = os.path.join(config.getdir('LOG_DIR'), metplus_log) + + if not metplus_log: print('Logging to terminal only') + else: + print('Logging to %s' % metplus_log) # set LOG_METPLUS with timestamp substituted config.set('config', 'LOG_METPLUS', metplus_log) @@ -342,6 +346,13 @@ def get_logger(config): f' {log_level_terminal}') sys.exit(1) + # create log formatter from config settings + formatter = METplusLogFormatter(config) + + # do not send logs up to root logger handlers + logger.propagate = False + + # set up logging file handler if logging to a file metpluslog = config.getstr('config', 'LOG_METPLUS', '') if not metpluslog: logger.setLevel(log_level_terminal_val) @@ -355,23 +366,17 @@ def get_logger(config): if not os.path.exists(dir_name): mkdir_p(dir_name) - # do not send logs up to root logger handlers - logger.propagate = False - - # create log formatter from config settings - formatter = METplusLogFormatter(config) - # set up the file logging file_handler = logging.FileHandler(metpluslog, mode='a') file_handler.setFormatter(formatter) file_handler.setLevel(log_level_val) logger.addHandler(file_handler) - # set up console logging - stream_handler = logging.StreamHandler() - stream_handler.setFormatter(formatter) - stream_handler.setLevel(log_level_terminal_val) - logger.addHandler(stream_handler) + # set up console logging + stream_handler = logging.StreamHandler() + stream_handler.setFormatter(formatter) + stream_handler.setLevel(log_level_terminal_val) + logger.addHandler(stream_handler) # set add the logger to the config config.logger = logger diff --git a/metplus/util/run_util.py b/metplus/util/run_util.py index d84fafa4fb..994c68d7b5 100644 --- a/metplus/util/run_util.py +++ b/metplus/util/run_util.py @@ -1,10 +1,13 @@ import sys import os import shutil -import logging from datetime import datetime +from typing import NamedTuple, Union +from logging import Logger +import shlex + +from produtil.run import exe, run -from .constants import NO_COMMAND_WRAPPERS from .string_manip import get_logfile_info, log_terminal_includes_info from .system_util import get_user_info, write_list_to_file from .config_util import get_process_list, handle_env_var_config @@ -12,7 +15,103 @@ from .config_validate import validate_config_variables from .. import get_metplus_version from .config_metplus import setup -from . import camel_to_underscore, get_wrapper_instance +from . import get_wrapper_instance + + +class RunArgs(NamedTuple): + logger: Union[Logger, None] = None + log_path: Union[str, None] = None + skip_run: bool = False + log_met_to_metplus: bool = True + env: os._Environ = os.environ + copyable_env: str = '' + + +class PrintLogger(object): + def __init__(self): + self.info = print + self.debug = print + self.error = print + self.warning = print + + +def run_cmd(cmd, run_args): + if not cmd: + return 0 + + # if env not set, use os.environ + env = os.environ if run_args.env is None else run_args.env + if run_args.logger is not None: + logger = run_args.logger + else: + logger = PrintLogger() + + logger.info("COMMAND: %s" % cmd) + + # don't run app if DO_NOT_RUN_EXE is set to True + if run_args.skip_run: + logger.info("Not running command (DO_NOT_RUN_EXE = True)") + return 0 + + log_path = run_args.log_path + + # determine if command must be run in a shell + run_in_shell = '*' in cmd or ';' in cmd or '<' in cmd or '>' in cmd + + # Run the executable and pass the arguments as a sequence. + # Split the command in to a sequence using shell syntax. + the_exe = shlex.split(cmd)[0] + the_args = shlex.split(cmd)[1:] + if log_path: + logger.debug("Logging command output to: %s" % log_path) + _log_header_info(log_path, run_args.copyable_env, cmd, run_args.log_met_to_metplus) + + if run_in_shell: + cmd_exe = exe('sh')['-c', cmd].env(**env).err2out() >> log_path + else: + cmd_exe = exe(the_exe)[the_args].env(**env).err2out() >> log_path + else: + if run_in_shell: + cmd_exe = exe('sh')['-c', cmd].env(**env) + else: + cmd_exe = exe(the_exe)[the_args].env(**env).err2out() + + # get current time to calculate total time to run command + start_cmd_time = datetime.now() + + # run command + try: + ret = run(cmd_exe) + except Exception as err: + logger.error(f'Exception occurred: {err}') + ret = -1 + else: + # calculate time to run + end_cmd_time = datetime.now() + total_cmd_time = end_cmd_time - start_cmd_time + logger.info(f'Finished running {the_exe} - took {total_cmd_time}') + + return ret + + +def _log_header_info(log_path, copyable_env, cmd, log_met_to_metplus): + with open(log_path, 'a+') as log_file_handle: + # if logging MET command to its own log file, + # add command that was run to that log + if not log_met_to_metplus: + # if environment variables were set and available, + # write them to MET tool log + if copyable_env: + log_file_handle.write( + "\nCOPYABLE ENVIRONMENT FOR NEXT COMMAND:\n") + log_file_handle.write(f"{copyable_env}\n\n") + else: + log_file_handle.write('\n') + + log_file_handle.write(f"COMMAND:\n{cmd}\n\n") + + # write line to designate where MET tool output starts + log_file_handle.write("OUTPUT:\n") def pre_run_setup(config_inputs): @@ -63,19 +162,13 @@ def pre_run_setup(config_inputs): f"generated in {sed_file}") logger.error("Correct configuration variables and rerun. Exiting.") - logger.info("Check the log file for more information: " - f"{get_logfile_info(config)}") + logger.info(f"Check the log file for more information: {log_file}") sys.exit(1) if not config.getdir('MET_INSTALL_DIR', must_exist=True): logger.error('MET_INSTALL_DIR must be set correctly to run METplus') sys.exit(1) - # set staging dir to OUTPUT_BASE/stage if not set - if not config.has_option('config', 'STAGING_DIR'): - config.set('config', 'STAGING_DIR', - os.path.join(config.getdir('OUTPUT_BASE'), "stage")) - # handle dir to write temporary files handle_tmp_dir(config) diff --git a/metplus/util/string_manip.py b/metplus/util/string_manip.py index 8fcfeab8dd..ee23b4fc9c 100644 --- a/metplus/util/string_manip.py +++ b/metplus/util/string_manip.py @@ -570,6 +570,33 @@ def find_indices_in_config_section(regex, config, sec='config', return indices +def get_log_path(config, logfile=None): + """!Returns the location of where the command output will be sent. + The METplus log, the MET log, or tty. + + @param config METplusConfig object to read + @param logfile file name to use if logging to a separate file + @returns Log file path or None if logging to terminal + """ + # if LOG_METPLUS is unset or empty, log to terminal + metplus_log = config.getstr('config', 'LOG_METPLUS', '') + if not metplus_log: + return None + + # return METplus log file if logging all output there + if config.getbool('config', 'LOG_MET_OUTPUT_TO_METPLUS') or logfile is None: + return metplus_log + + log_path = os.path.join(config.getdir('LOG_DIR'), logfile) + + # add log timestamp to log filename if set + log_timestamp = config.getstr('config', 'LOG_TIMESTAMP', '') + if log_timestamp: + log_path = f'{log_path}.{log_timestamp}' + + return log_path + + def get_logfile_info(config): """!Get path to log file from LOG_METPLUS config variable or return a useful message if it is not set to instruct users how to set it. @@ -577,6 +604,8 @@ def get_logfile_info(config): @param config METplusConfig object to read LOG_METPLUS from @returns path to log file or message if unset """ + if config.getbool('config', 'LOG_TO_TERMINAL_ONLY'): + return 'Set LOG_TO_TERMINAL_ONLY=False to write logs to a file' log_file = config.getstr('config', 'LOG_METPLUS', '') return log_file if log_file else 'Set LOG_METPLUS to write logs to a file' diff --git a/metplus/util/string_template_substitution.py b/metplus/util/string_template_substitution.py index d181332b9f..424c15c46d 100644 --- a/metplus/util/string_template_substitution.py +++ b/metplus/util/string_template_substitution.py @@ -127,7 +127,7 @@ def format_hms(fmt, obj): # i.e. 90 minutes %M => 90, but %H%M => 0130 days = obj // 86400 hours = obj // 3600 - minutes = obj // 60 + minutes = obj // 60 seconds = obj # if days are specified, change hours, minutes, and seconds to relative diff --git a/metplus/wrappers/command_builder.py b/metplus/wrappers/command_builder.py index 3a70fe99ea..13ee4b5a38 100755 --- a/metplus/wrappers/command_builder.py +++ b/metplus/wrappers/command_builder.py @@ -10,14 +10,11 @@ """ import os -import sys import glob from datetime import datetime from abc import ABCMeta from inspect import getframeinfo, stack -from .command_runner import CommandRunner - from ..util.constants import PYTHON_EMBEDDING_TYPES, COMPRESSION_EXTENSIONS from ..util import getlist, preprocess_file, loop_over_times_and_call from ..util import do_string_sub, ti_calculate, get_seconds_from_string @@ -32,6 +29,8 @@ from ..util import get_wrapper_name, is_python_script from ..util.met_config import add_met_config_dict, handle_climo_dict from ..util import mkdir_p, get_skip_times +from ..util import get_log_path, RunArgs, run_cmd + # pylint:disable=pointless-string-statement '''!@namespace CommandBuilder @@ -119,12 +118,6 @@ def __init__(self, config, instance=None): self.check_for_externals() - self.cmdrunner = CommandRunner( - self.config, logger=self.logger, - verbose=self.c_dict['VERBOSITY'], - skip_run=self.c_dict.get('DO_NOT_RUN_EXE', False), - ) - # set log name to app name by default # any wrappers with a name different than the primary app that is run # should override this value in their init function after the call @@ -1275,27 +1268,35 @@ def run_command(self, cmd, cmd_name=None): if self.instance: log_name = f"{log_name}.{self.instance}" - ret, out_cmd = self.cmdrunner.run_cmd(cmd, - env=self.env, - log_name=log_name, - copyable_env=self.get_env_copy()) + log_name = log_name if log_name else os.path.basename(cmd.split()[0]) + + # Determine where to send the output from the MET command. + log_path = get_log_path(self.config, logfile=log_name+'.log') + + run_arguments = RunArgs( + logger=self.logger, + log_path=log_path, + skip_run=self.c_dict.get('DO_NOT_RUN_EXE', False), + log_met_to_metplus=self.config.getbool('config', 'LOG_MET_OUTPUT_TO_METPLUS'), + env=self.env, + copyable_env=self.get_env_copy(), + ) + ret = self.run_cmd(cmd, run_arguments) if not ret: return True self.log_error(f"Command returned a non-zero return code: {cmd}") - logfile_path = self.config.getstr('config', 'LOG_METPLUS') - if not logfile_path: + if log_path is None: return False - # if MET output is written to its own logfile, get that filename - if not self.config.getbool('config', 'LOG_MET_OUTPUT_TO_METPLUS'): - logfile_path = logfile_path.replace('run_metplus', log_name) - self.logger.info("Check the logfile for more information on why " - f"it failed: {logfile_path}") + f"it failed: {log_path}") return False + def run_cmd(self, cmd, run_args): + return run_cmd(cmd, run_args) + def run_all_times(self, custom=None): """! Loop over time range specified in conf file and call METplus wrapper for each time diff --git a/metplus/wrappers/command_runner.py b/metplus/wrappers/command_runner.py deleted file mode 100755 index 9c94738b5d..0000000000 --- a/metplus/wrappers/command_runner.py +++ /dev/null @@ -1,181 +0,0 @@ -""" -File Name: command_runner.py -Contact(s): Jim Frimel -Abstract: -History Log: Initial version -Usage: Use as a has-a relationship with your object or module. - Object has-a command runner. -Parameters: None -Input Files: N/A -Output Files: N/A -""" - -##@namespace command_runner -# The purpose of this class is to run the external MET executables -# and other ancillary external programs used in METplus, such as -# wgrib2, ncdump, plot_tcmpr.R -# -# It also centralizes the output redirection to the -# METplus logs, MET logs or TTY. -# -# One BIG underlying assumption is that all commands are run -# the same way in terms of the Runner object and the Run command -# executed. -# -# Originally this capability (the methods) was placed in the -# CommandBuilder but it seemed to separating out made sense. -# CommandBuilder now has-a CommandRunner. But being in its own class -# allows it to be used elsewhere if needed. -# -# It creates a produtil Runnable object -# It determines where to redirect the output -# METplus log file, MET logs, or TTY -# It runs the Runnable object -# - -import os -from produtil.run import exe, run -import shlex -from datetime import datetime, timezone - - -class CommandRunner(object): - """! Class for Creating and Running External Programs - """ - def __init__(self, config, logger=None, verbose=2, skip_run=False): - """!Class for Creating and Running External Programs. - It was intended to handle the MET executables but - can be used by other executables.""" - self.logger = logger - self.config = config - self.verbose = verbose - self.skip_run = skip_run - self.log_met_to_metplus = config.getbool('config', - 'LOG_MET_OUTPUT_TO_METPLUS') - - def run_cmd(self, cmd, env=None, log_name=None, - copyable_env=None, **kwargs): - """!The command cmd is a string which is converted to a produtil - exe Runner object and than run. Output of the command may also - be redirected to either METplus log, MET log, or TTY. - - Some subclasses of CommandBuilder ie. series_by_init_wrapper, run - non MET commands ie. convert, in addition to MET binary commands, - ie. regrid_data_plane. - - Args: - @param cmd: A string, Command used in the produtil exe Runner object. - @param env: Default None, environment for run to pass in, uses - os.environ if not set. - @param log_name: Used only when ismetcmd=True, The name of the exectable - being run. - @param kwargs Other options sent to the produtil Run constructor - """ - if cmd is None: - return cmd - - # if env not set, use os.environ - env = os.environ if env is None else env - - self.logger.info("COMMAND: %s" % cmd) - - # don't run app if DO_NOT_RUN_EXE is set to True - if self.skip_run: - self.logger.info("Not running command (DO_NOT_RUN_EXE = True)") - return 0, cmd - - log_name = log_name if log_name else os.path.basename(cmd.split()[0]) - - # Determine where to send the output from the MET command. - log_dest = self.get_log_path(log_filename=log_name+'.log') - - # determine if command must be run in a shell - run_inshell = '*' in cmd or ';' in cmd or '<' in cmd or '>' in cmd - - # KEEP This comment as a reference note. - # Run the executable in a new process instead of through a shell. - # FYI. We were originally running the command through a shell - # which also works just fine. IF we go back to running through - # a shell, The string ,cmd, is formatted exactly as is needed. - # By formatted, it is as it would be when typed at the shell prompt. - # This includes, for example, quoting or backslash escaping filenames - # with spaces in them. - - # Run the executable and pass the arguments as a sequence. - # Split the command in to a sequence using shell syntax. - the_exe = shlex.split(cmd)[0] - the_args = shlex.split(cmd)[1:] - if log_dest: - self.logger.debug("Logging command output to: %s" % log_dest) - self.log_header_info(log_dest, copyable_env, cmd) - - if run_inshell: - cmd_exe = exe('sh')['-c', cmd].env(**env).err2out() >> log_dest - else: - cmd_exe = exe(the_exe)[the_args].env(**env).err2out() >> log_dest - else: - if run_inshell: - cmd_exe = exe('sh')['-c', cmd].env(**env) - else: - cmd_exe = exe(the_exe)[the_args].env(**env).err2out() - - # get current time to calculate total time to run command - start_cmd_time = datetime.now() - - # run command - try: - ret = run(cmd_exe, **kwargs) - except Exception: - ret = -1 - else: - # calculate time to run - end_cmd_time = datetime.now() - total_cmd_time = end_cmd_time - start_cmd_time - self.logger.info(f'Finished running {the_exe} ' - f'- took {total_cmd_time}') - - return ret, cmd - - def log_header_info(self, log_dest, copyable_env, cmd): - with open(log_dest, 'a+') as log_file_handle: - # if logging MET command to its own log file, - # add command that was run to that log - if not self.log_met_to_metplus: - # if environment variables were set and available, - # write them to MET tool log - if copyable_env: - log_file_handle.write( - "\nCOPYABLE ENVIRONMENT FOR NEXT COMMAND:\n") - log_file_handle.write(f"{copyable_env}\n\n") - else: - log_file_handle.write('\n') - - log_file_handle.write(f"COMMAND:\n{cmd}\n\n") - - # write line to designate where MET tool output starts - log_file_handle.write("OUTPUT:\n") - - def get_log_path(self, log_filename): - """!Returns the location of where the command output will be sent. - The METplus log, the MET log, or tty. - - @param log_filename file name to use if logging to a separate file - @returns Log file path or None if logging to terminal - """ - # if LOG_METPLUS is unset or empty, log to terminal - metplus_log = self.config.getstr('config', 'LOG_METPLUS', '') - if not metplus_log: - return None - - # return METplus log file if logging all output there - if self.log_met_to_metplus: - return metplus_log - - log_path = os.path.join(self.config.getdir('LOG_DIR'), log_filename) - - # add log timestamp to log filename if set - log_timestamp = self.config.getstr('config', 'LOG_TIMESTAMP', '') - if log_timestamp: - log_path = f'{log_path}.{log_timestamp}' - - return log_path diff --git a/parm/metplus_config/defaults.conf b/parm/metplus_config/defaults.conf index 850eb68434..ba67ccd233 100644 --- a/parm/metplus_config/defaults.conf +++ b/parm/metplus_config/defaults.conf @@ -78,6 +78,7 @@ SCRUB_STAGING_DIR = True # Log File Information (Where to write logs files) # ############################################################################### +LOG_TO_TERMINAL_ONLY = False LOG_METPLUS = {LOG_DIR}/metplus.log.{LOG_TIMESTAMP}