From 2190c52266171426f2b4f983afffc987ce9b1c4b Mon Sep 17 00:00:00 2001 From: Will Usher Date: Fri, 29 Mar 2019 14:18:03 +0000 Subject: [PATCH 1/5] Remove top level verbosity cli argument --- README.rst | 4 +--- docs/getting_started.rst | 4 +--- src/smif/cli/__init__.py | 37 +++++++++++++++++-------------------- tests/cli/test_cli.py | 17 +++++++++-------- 4 files changed, 28 insertions(+), 34 deletions(-) diff --git a/README.rst b/README.rst index 7e8736631..0b9b9192a 100644 --- a/README.rst +++ b/README.rst @@ -222,7 +222,7 @@ and simulation model. To see all options and flags:: $ smif --help - usage: smif [-h] [-V] [-v] {setup,list,run} ... + usage: smif [-h] [-V] {setup,list,run} ... Command line tools for smif @@ -236,8 +236,6 @@ To see all options and flags:: optional arguments: -h, --help show this help message and exit -V, --version show the current version of smif - -v, --verbose show messages: -v to see messages reporting on progress, - -vv to see debug messages. Citation ======== diff --git a/docs/getting_started.rst b/docs/getting_started.rst index c85d455bd..00c58cdf5 100644 --- a/docs/getting_started.rst +++ b/docs/getting_started.rst @@ -18,7 +18,7 @@ Setup First, check smif has installed correctly by typing on the command line:: $ smif - usage: smif [-h] [-V] [-v] {setup,list,app,run} ... + usage: smif [-h] [-V] {setup,list,app,run} ... Command line tools for smif @@ -32,8 +32,6 @@ First, check smif has installed correctly by typing on the command line:: optional arguments: -h, --help show this help message and exit -V, --version show the current version of smif - -v, --verbose show messages: -v to see messages reporting on - progress, -vv to see debug messages. You can also check which version is installed:: diff --git a/src/smif/cli/__init__.py b/src/smif/cli/__init__.py index 8f2de6ff5..b525edab1 100644 --- a/src/smif/cli/__init__.py +++ b/src/smif/cli/__init__.py @@ -65,15 +65,28 @@ """ from __future__ import print_function +import logging +import logging.config +import os +import sys +from argparse import ArgumentParser + +import pkg_resources + +import smif +import smif.cli.log +from smif.controller import (ModelRunScheduler, copy_project_folder, + execute_model_run) +from smif.data_layer import Store +from smif.data_layer.file import (CSVDataStore, FileMetadataStore, + ParquetDataStore, YamlConfigStore) +from smif.http_api import create_app + try: import _thread except ImportError: import thread as _thread -import logging -import logging.config -import os -import pkg_resources try: import win32api @@ -81,18 +94,6 @@ except ImportError: USE_WIN32 = False -from argparse import ArgumentParser -import sys - -import smif -import smif.cli.log - -from smif.controller import copy_project_folder, execute_model_run, ModelRunScheduler -from smif.http_api import create_app -from smif.data_layer import Store -from smif.data_layer.file import (CSVDataStore, FileMetadataStore, ParquetDataStore, - YamlConfigStore) - __author__ = "Will Usher, Tom Russell" __copyright__ = "Will Usher, Tom Russell" @@ -221,10 +222,6 @@ def parse_arguments(): action='version', version="smif " + smif.__version__, help='show the current version of smif') - parser.add_argument('-v', '--verbose', - action='count', - help='show messages: -v to see messages reporting on progress, ' + - '-vv to see debug messages.') parent_parser = ArgumentParser(add_help=False) parent_parser.add_argument('-v', '--verbose', diff --git a/tests/cli/test_cli.py b/tests/cli/test_cli.py index cab5b3c52..fd2ce1d83 100644 --- a/tests/cli/test_cli.py +++ b/tests/cli/test_cli.py @@ -7,8 +7,9 @@ from tempfile import TemporaryDirectory from unittest.mock import call, patch -import smif from pytest import fixture + +import smif from smif.cli import confirm, parse_arguments, setup_project_folder @@ -16,7 +17,7 @@ def tmp_sample_project(tmpdir_factory): test_folder = tmpdir_factory.mktemp("smif") subprocess.run( - ["smif", "-v", "setup", "-d", str(test_folder)], + ["smif", "setup", "-d", str(test_folder), "-v"], stdout=subprocess.PIPE, stderr=subprocess.PIPE ) @@ -49,8 +50,8 @@ def test_fixture_single_run(tmp_sample_project): """Test running the (default) binary-filesystem-based single_run fixture """ config_dir = tmp_sample_project - output = subprocess.run(["smif", "-v", "run", "-d", config_dir, - "energy_central"], + output = subprocess.run(["smif", "run", "-d", config_dir, + "energy_central", "-v"], stdout=subprocess.PIPE, stderr=subprocess.PIPE) print(output.stdout.decode("utf-8")) print(output.stderr.decode("utf-8"), file=sys.stderr) @@ -62,8 +63,8 @@ def test_fixture_single_run_csv(tmp_sample_project): """Test running the csv-filesystem-based single_run fixture """ output = subprocess.run( - ["smif", "-v", "run", "-i", "local_csv", "-d", tmp_sample_project, - "energy_central"], + ["smif", "run", "-i", "local_csv", "-d", tmp_sample_project, + "energy_central", "-v"], stdout=subprocess.PIPE, stderr=subprocess.PIPE ) @@ -77,7 +78,7 @@ def test_fixture_single_run_warm(tmp_sample_project): """Test running the (default) single_run fixture with warm setting enabled """ config_dir = tmp_sample_project - output = subprocess.run(["smif", "-v", "run", "-w", "-d", config_dir, + output = subprocess.run(["smif", "run", "-v", "-w", "-d", config_dir, "energy_central"], stdout=subprocess.PIPE, stderr=subprocess.PIPE) print(output.stdout.decode("utf-8")) @@ -90,7 +91,7 @@ def test_fixture_batch_run(tmp_sample_project): """Test running the multiple modelruns using the batch_run option """ config_dir = tmp_sample_project - output = subprocess.run(["smif", "-v", "run", "-b", "-d", config_dir, + output = subprocess.run(["smif", "run", "-v", "-b", "-d", config_dir, os.path.join(config_dir, "batchfile")], stdout=subprocess.PIPE, stderr=subprocess.PIPE) print(output.stdout.decode("utf-8")) From 000a5756a8552d4241a905cb55e0d7974f8ed033 Mon Sep 17 00:00:00 2001 From: Tom Russell Date: Fri, 29 Mar 2019 17:40:12 +0000 Subject: [PATCH 2/5] Move logging setup into a function to be called after argparsing This should avoid the confusing effect of -v and -vv arguments working wherever they may appear in the command. --- src/smif/cli/__init__.py | 2 +- src/smif/cli/log.py | 102 ++++++++++++++++++--------------------- 2 files changed, 47 insertions(+), 57 deletions(-) diff --git a/src/smif/cli/__init__.py b/src/smif/cli/__init__.py index b525edab1..3a880cdec 100644 --- a/src/smif/cli/__init__.py +++ b/src/smif/cli/__init__.py @@ -66,7 +66,6 @@ from __future__ import print_function import logging -import logging.config import os import sys from argparse import ArgumentParser @@ -331,6 +330,7 @@ def main(arguments=None): """ parser = parse_arguments() args = parser.parse_args(arguments) + smif.cli.log.setup_logging(args.verbose) def exception_handler(exception_type, exception, traceback, debug_hook=sys.excepthook): if args.verbose: diff --git a/src/smif/cli/log.py b/src/smif/cli/log.py index 26d2cfc6e..256e91a4e 100644 --- a/src/smif/cli/log.py +++ b/src/smif/cli/log.py @@ -5,37 +5,6 @@ import sys from collections import OrderedDict -LOGGING_CONFIG = { - 'version': 1, - 'formatters': { - 'default': { - 'format': '%(asctime)s %(name)-12s: %(levelname)-8s %(message)s' - }, - 'message': { - 'format': '\033[1;34m%(levelname)-8s\033[0m %(message)s' - } - }, - 'handlers': { - 'file': { - 'class': 'logging.FileHandler', - 'level': 'DEBUG', - 'formatter': 'default', - 'filename': 'smif.log', - 'mode': 'a', - 'encoding': 'utf-8' - }, - 'stream': { - 'class': 'logging.StreamHandler', - 'formatter': 'message', - 'level': 'DEBUG' - } - }, - 'root': { - 'handlers': ['file', 'stream'], - 'level': 'DEBUG' - } -} - # Make profiling methods available through the logger def profiling_start(self, operation, key): @@ -100,28 +69,49 @@ def summary(self, *args, **kws): self._log(logging.INFO, entry, args) -logging.Logger.profiling_start = profiling_start -logging.Logger.profiling_stop = profiling_stop -logging.Logger.summary = summary -logging.Logger._profile = OrderedDict() - -# Configure logging once, outside of any dependency on argparse -VERBOSITY = None -if '--verbose' in sys.argv: - VERBOSITY = sys.argv.count('--verbose') -else: - for arg in sys.argv: - if re.match(r'\A-v+\Z', arg): - VERBOSITY = len(arg) - 1 - break - -if VERBOSITY is None: - LOGGING_CONFIG['root']['level'] = logging.WARNING -elif VERBOSITY == 1: - LOGGING_CONFIG['root']['level'] = logging.INFO -else: - LOGGING_CONFIG['root']['level'] = logging.DEBUG - -logging.config.dictConfig(LOGGING_CONFIG) -LOGGER = logging.getLogger(__name__) -LOGGER.debug('Debug logging enabled.') +def setup_logging(loglevel): + config = { + 'version': 1, + 'formatters': { + 'default': { + 'format': '%(asctime)s %(name)-12s: %(levelname)-8s %(message)s' + }, + 'message': { + 'format': '\033[1;34m%(levelname)-8s\033[0m %(message)s' + } + }, + 'handlers': { + 'file': { + 'class': 'logging.FileHandler', + 'level': 'DEBUG', + 'formatter': 'default', + 'filename': 'smif.log', + 'mode': 'a', + 'encoding': 'utf-8' + }, + 'stream': { + 'class': 'logging.StreamHandler', + 'formatter': 'message', + 'level': 'DEBUG' + } + }, + 'root': { + 'handlers': ['file', 'stream'], + 'level': 'DEBUG' + } + } + logging.Logger.profiling_start = profiling_start + logging.Logger.profiling_stop = profiling_stop + logging.Logger.summary = summary + logging.Logger._profile = OrderedDict() + + if loglevel is None: + config['root']['level'] = logging.WARNING + elif loglevel == 1: + config['root']['level'] = logging.INFO + else: + config['root']['level'] = logging.DEBUG + + logging.config.dictConfig(config) + LOGGER = logging.getLogger(__name__) + LOGGER.debug('Debug logging enabled.') From c9399d084a87bab1ee086dfc960dde70c5fc10a2 Mon Sep 17 00:00:00 2001 From: Tom Russell Date: Fri, 29 Mar 2019 17:55:44 +0000 Subject: [PATCH 3/5] Patch logging.Logger at smif.cli.log module level --- src/smif/cli/log.py | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/src/smif/cli/log.py b/src/smif/cli/log.py index 256e91a4e..6b81b7e77 100644 --- a/src/smif/cli/log.py +++ b/src/smif/cli/log.py @@ -100,10 +100,6 @@ def setup_logging(loglevel): 'level': 'DEBUG' } } - logging.Logger.profiling_start = profiling_start - logging.Logger.profiling_stop = profiling_stop - logging.Logger.summary = summary - logging.Logger._profile = OrderedDict() if loglevel is None: config['root']['level'] = logging.WARNING @@ -113,5 +109,10 @@ def setup_logging(loglevel): config['root']['level'] = logging.DEBUG logging.config.dictConfig(config) - LOGGER = logging.getLogger(__name__) - LOGGER.debug('Debug logging enabled.') + logging.debug('Debug logging enabled.') + + +logging.Logger.profiling_start = profiling_start +logging.Logger.profiling_stop = profiling_stop +logging.Logger.summary = summary +logging.Logger._profile = OrderedDict() From 919ca9891404cf5adc513143c0337dd56efb04c8 Mon Sep 17 00:00:00 2001 From: Tom Russell Date: Fri, 29 Mar 2019 17:56:16 +0000 Subject: [PATCH 4/5] Avoid module-level LOGGER objects (prefer logging.info etc.) --- src/smif/cli/__init__.py | 10 ++++------ src/smif/controller/build.py | 27 +++++++++++++-------------- src/smif/controller/execute.py | 10 ++++------ src/smif/controller/setup.py | 4 +--- 4 files changed, 22 insertions(+), 29 deletions(-) diff --git a/src/smif/cli/__init__.py b/src/smif/cli/__init__.py index 3a880cdec..eece5707a 100644 --- a/src/smif/cli/__init__.py +++ b/src/smif/cli/__init__.py @@ -99,9 +99,6 @@ __license__ = "mit" -LOGGER = logging.getLogger(__name__) - - def list_model_runs(args): """List the model runs defined in the config """ @@ -119,7 +116,8 @@ def run_model_runs(args): ---------- args """ - LOGGER.profiling_start('run_model_runs', '{:s}, {:s}, {:s}'.format( + logger = logging.getLogger(__name__) + logger.profiling_start('run_model_runs', '{:s}, {:s}, {:s}'.format( args.modelrun, args.interface, args.directory)) if args.batchfile: with open(args.modelrun, 'r') as f: @@ -129,9 +127,9 @@ def run_model_runs(args): store = _get_store(args) execute_model_run(model_run_ids, store, args.warm) - LOGGER.profiling_stop('run_model_runs', '{:s}, {:s}, {:s}'.format( + logger.profiling_stop('run_model_runs', '{:s}, {:s}, {:s}'.format( args.modelrun, args.interface, args.directory)) - LOGGER.summary() + logger.summary() def _get_store(args): diff --git a/src/smif/controller/build.py b/src/smif/controller/build.py index 439d9d69b..9d33cc04c 100644 --- a/src/smif/controller/build.py +++ b/src/smif/controller/build.py @@ -8,8 +8,6 @@ from smif.exception import SmifDataNotFoundError from smif.model import ScenarioModel, SosModel -LOGGER = logging.getLogger(__name__) - def get_model_run_definition(store, modelrun): """Builds the model run @@ -31,26 +29,26 @@ def get_model_run_definition(store, modelrun): try: model_run_config = store.read_model_run(modelrun) except SmifDataNotFoundError: - LOGGER.error("Model run %s not found. Run 'smif list' to see available model runs.", + logging.error("Model run %s not found. Run 'smif list' to see available model runs.", modelrun) exit(-1) - LOGGER.info("Running %s", model_run_config['name']) - LOGGER.debug("Model Run: %s", model_run_config) + logging.info("Running %s", model_run_config['name']) + logging.debug("Model Run: %s", model_run_config) sos_model_config = store.read_sos_model(model_run_config['sos_model']) sector_models = get_sector_models(sos_model_config['sector_models'], store) - LOGGER.debug("Sector models: %s", sector_models) + logging.debug("Sector models: %s", sector_models) scenario_models = get_scenario_models(model_run_config['scenarios'], store) - LOGGER.debug("Scenario models: %s", [model.name for model in scenario_models]) + logging.debug("Scenario models: %s", [model.name for model in scenario_models]) sos_model = SosModel.from_dict(sos_model_config, sector_models + scenario_models) model_run_config['sos_model'] = sos_model - LOGGER.debug("Model list: %s", list(model.name for model in sos_model.models)) + logging.debug("Model list: %s", list(model.name for model in sos_model.models)) model_run_config['strategies'] = store.read_strategies(model_run_config['name']) - LOGGER.debug("Strategies: %s", [s['type'] for s in model_run_config['strategies']]) + logging.debug("Strategies: %s", [s['type'] for s in model_run_config['strategies']]) return model_run_config @@ -78,7 +76,7 @@ def get_scenario_models(scenarios, handler): scenario_definition['outputs'] = scenario_definition['provides'] del scenario_definition['provides'] - LOGGER.debug("Scenario definition: %s", scenario_name) + logging.debug("Scenario definition: %s", scenario_name) scenario_model = ScenarioModel.from_dict(scenario_definition) scenario_models.append(scenario_model) @@ -123,7 +121,8 @@ def build_model_run(model_run_config): ------- `smif.controller.modelrun.ModelRun` """ - LOGGER.profiling_start('build_model_run', model_run_config['name']) + logger = logging.getLogger() + logger.profiling_start('build_model_run', model_run_config['name']) try: builder = ModelRunBuilder() builder.construct(model_run_config) @@ -133,10 +132,10 @@ def build_model_run(model_run_config): traceback.print_exception(err_type, err_value, err_traceback) err_msg = str(error) if err_msg: - LOGGER.error("An AssertionError occurred (%s) see details above.", err_msg) + logger.error("An AssertionError occurred (%s) see details above.", err_msg) else: - LOGGER.error("An AssertionError occurred, see details above.") + logger.error("An AssertionError occurred, see details above.") exit(-1) - LOGGER.profiling_stop('build_model_run', model_run_config['name']) + logger.profiling_stop('build_model_run', model_run_config['name']) return modelrun diff --git a/src/smif/controller/execute.py b/src/smif/controller/execute.py index 148d3e9d5..989daefbd 100644 --- a/src/smif/controller/execute.py +++ b/src/smif/controller/execute.py @@ -4,8 +4,6 @@ from smif.controller.build import build_model_run, get_model_run_definition from smif.exception import SmifModelRunError -LOGGER = logging.getLogger(__name__) - def execute_model_run(model_run_ids, store, warm=False): """Runs the model run @@ -17,15 +15,15 @@ def execute_model_run(model_run_ids, store, warm=False): """ model_run_definitions = [] for model_run in model_run_ids: - LOGGER.info("Getting model run definition for '%s'", model_run) + logging.info("Getting model run definition for '%s'", model_run) model_run_definitions.append(get_model_run_definition(store, model_run)) for model_run_config in model_run_definitions: - LOGGER.info("Build model run from configuration data") + logging.info("Build model run from configuration data") modelrun = build_model_run(model_run_config) - LOGGER.info("Running model run %s", modelrun.name) + logging.info("Running model run %s", modelrun.name) try: if warm: @@ -33,7 +31,7 @@ def execute_model_run(model_run_ids, store, warm=False): else: modelrun.run(store) except SmifModelRunError as ex: - LOGGER.exception(ex) + logging.exception(ex) exit(1) print("Model run '%s' complete" % modelrun.name) diff --git a/src/smif/controller/setup.py b/src/smif/controller/setup.py index 57ac087b9..4a9b626c2 100644 --- a/src/smif/controller/setup.py +++ b/src/smif/controller/setup.py @@ -4,8 +4,6 @@ import pkg_resources -LOGGER = logging.getLogger(__name__) - def copy_project_folder(directory): """Creates folder structure in the target directory @@ -20,7 +18,7 @@ def copy_project_folder(directory): dirname = "the current directory" else: dirname = directory - LOGGER.info("Created sample project in %s", dirname) + logging.info("Created sample project in %s", dirname) def _recursive_overwrite(pkg, src, dest): From c1ffc772e106244ca7b8431dff0c80ec17cdab84 Mon Sep 17 00:00:00 2001 From: Tom Russell Date: Fri, 29 Mar 2019 17:56:31 +0000 Subject: [PATCH 5/5] Fix verbosity CLI test --- tests/cli/test_cli.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/cli/test_cli.py b/tests/cli/test_cli.py index fd2ce1d83..d756f0c1b 100644 --- a/tests/cli/test_cli.py +++ b/tests/cli/test_cli.py @@ -174,12 +174,12 @@ def test_version_display(): def test_verbose_debug(): """Expect debug message from `smif -vv` """ - output = subprocess.run(['smif', '-vv'], stderr=subprocess.PIPE) + output = subprocess.run(['smif', 'list', '-vv'], stderr=subprocess.PIPE) assert 'DEBUG' in str(output.stderr) def test_verbose_debug_alt(): """Expect debug message from `smif --verbose --verbose` """ - output = subprocess.run(['smif', '--verbose', '--verbose'], stderr=subprocess.PIPE) + output = subprocess.run(['smif', 'list', '--verbose', '--verbose'], stderr=subprocess.PIPE) assert 'DEBUG' in str(output.stderr)