Merge pull request #40 from tomalrussell/feature/verbose_logging_option

Feature/verbose logging option.  Looks good @tomalrussell

smif/cli/__init__.py

@@ -37,8 +37,8 @@
 import logging
 import logging.config
 import os
+import re
 import sys
-import traceback
 from argparse import ArgumentParser
 
 from smif.sos_model import SosModelBuilder
@@ -66,7 +66,7 @@
             'class': 'logging.FileHandler',
             'level': 'DEBUG',
             'formatter': 'default',
-            'filename': 'cli.log',
+            'filename': 'smif.log',
             'mode': 'a',
             'encoding': 'utf-8'
         },
@@ -82,8 +82,26 @@
     }
 }
 
+# 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
+elif VERBOSITY >= 2:
+    LOGGING_CONFIG['root']['level'] = logging.DEBUG
+
 logging.config.dictConfig(LOGGING_CONFIG)
 LOGGER = logging.getLogger(__name__)
+LOGGER.debug('Debug logging enabled.')
 
 
 def setup_project_folder(project_path):
@@ -175,9 +193,7 @@ def validate_config(args):
         except Exception as error:
             # should not raise error, so exit
             log_validation_errors()
-            LOGGER.debug("Unexpected error validating config: %s", error)
-            if LOGGER.isEnabledFor(logging.DEBUG):
-                traceback.print_tb(error.__traceback__)
+            LOGGER.exception("Unexpected error validating config: %s", error)
             exit(-1)
 
         log_validation_errors()
@@ -252,6 +268,10 @@ def parse_arguments():
 
     """
     parser = ArgumentParser(description='Command line tools for smif')
+    parser.add_argument('-v', '--verbose',
+                        action='count',
+                        help='show messages: -v to see messages reporting on progress, ' +
+                        '-vv to see debug messages.')
     subparsers = parser.add_subparsers()
 
     # VALIDATE
@@ -342,6 +362,7 @@ def main(arguments=None):
     """
     parser = parse_arguments()
     args = parser.parse_args(arguments)
+
     if 'func' in args:
         args.func(args)
     else:

tests/cli/test_cli.py

@@ -2,6 +2,7 @@
 """
 
 import os
+import subprocess
 from tempfile import TemporaryDirectory
 from unittest.mock import call, patch
 
@@ -115,7 +116,7 @@ def test_validation_invalid(
         setup_folder_structure,
         setup_project_folder,
         setup_timesteps_file_invalid):
-    """Ensure configuration file is valid
+    """Ensure invalid configuration file raises error
     """
     config_file = os.path.join(str(setup_folder_structure), 'config', 'model.yaml')
     args = get_args(['validate', config_file])
@@ -163,3 +164,25 @@ def test_confirm_repeat_message(mock_print, input):
     confirm()
     input.assert_has_calls([call('Confirm [n]|y: '), call('Confirm [n]|y: ')])
     mock_print.assert_called_with('please enter y or n.')
+
+
+def test_verbose_debug():
+    """Expect debug message from `smif -vv`
+    """
+    output = subprocess.run(['smif', '-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)
+    assert 'DEBUG' in str(output.stderr)
+
+
+def test_verbose_info(setup_folder_structure, setup_project_folder):
+    """Expect info message from `smif -v validate <config_file>`
+    """
+    config_file = os.path.join(str(setup_folder_structure), 'config', 'model.yaml')
+    output = subprocess.run(['smif', '-v', 'validate', config_file], stderr=subprocess.PIPE)
+    assert 'INFO' in str(output.stderr)