ENH: Logging for skypy command line script and Pipeline class (#453)

Author: rrjbca

docs/pipeline/index.rst

@@ -21,6 +21,9 @@ fits files:
 
     $ skypy examples/galaxies/sdss_photometry.yml sdss_photometry.fits
 
+To view the progress of the pipeline as it runs you can enable logging using the
+`--verbose` flag.
+
 Config files are written in YAML format and read using the
 `~skypy.pipeline.load_skypy_yaml` funciton. Each entry in the config specifices
 an arbitrary variable, but there are also some particular fields that SkyPy uses:

skypy/pipeline/__init__.py

@@ -3,5 +3,9 @@
 dependencies and handle their outputs.
 """
 
+import logging
+
+log = logging.getLogger(__name__)
+
 from ._config import *  # noqa
 from ._pipeline import *  # noqa

skypy/pipeline/_items.py

@@ -1,6 +1,7 @@
 '''item types in the pipeline'''
 
 from collections.abc import Sequence, Mapping
+from . import log
 import inspect
 
 
@@ -88,4 +89,5 @@ def evaluate(self, pipeline):
         '''execute the call in the given pipeline'''
         args = pipeline.evaluate(self.args)
         kwargs = pipeline.evaluate(self.kwargs)
+        log.info(f"Calling {self.function.__name__}")
         return self.function(*args, **kwargs)

skypy/pipeline/_pipeline.py

@@ -9,6 +9,7 @@
 from collections.abc import Sequence, Mapping
 from ._config import load_skypy_yaml
 from ._items import Item, Call, Ref
+from . import log
 import networkx
 import pathlib
 
@@ -164,6 +165,7 @@ def execute(self, parameters={}):
 
         # Initialise cosmology from config parameters
         if self.cosmology is not None:
+            log.info("Setting cosmology")
             self.state['cosmology'] = self.evaluate(self.cosmology)
 
         # go through the jobs in dependency order
@@ -172,7 +174,8 @@ def execute(self, parameters={}):
             skip = node.get('skip', True)
             if skip:
                 continue
-            elif job in self.config:
+            log.info(f"Generating {job}")
+            if job in self.config:
                 settings = self.config.get(job)
                 self.state[job] = self.evaluate(settings)
             else:

skypy/pipeline/scripts/skypy.py

@@ -1,6 +1,7 @@
 '''skypy Command Line Script'''
 
 import argparse
+import logging
 from skypy import __version__ as skypy_version
 from skypy.pipeline import Pipeline, load_skypy_yaml
 import sys
@@ -14,21 +15,37 @@ def main(args=None):
     parser.add_argument('output', help='Output file name')
     parser.add_argument('-o', '--overwrite', action='store_true',
                         help='Whether to overwrite existing files')
+    parser.add_argument("-v", "--verbose", action="count", default=0,
+                        help="Increase logging verbosity")
+    parser.add_argument("-q", "--quiet", action="count", default=0,
+                        help="Decrease logging verbosity")
 
     # get system args if none passed
     if args is None:
         args = sys.argv[1:]
 
     args = parser.parse_args(args or ['--help'])
-    config = load_skypy_yaml(args.config)
+
+    # Setup skypy logger
+    default_level = logging._nameToLevel['WARNING']
+    logging_level = default_level + 10 * (args.quiet - args.verbose)
+    formatter = logging.Formatter('%(asctime)s [%(levelname)s] %(name)s: %(message)s')
+    stream_handler = logging.StreamHandler()
+    stream_handler.setLevel(logging_level)
+    stream_handler.setFormatter(formatter)
+    logger = logging.getLogger('skypy')
+    logger.setLevel(logging_level)
+    logger.addHandler(stream_handler)
 
     try:
+        config = load_skypy_yaml(args.config)
         pipeline = Pipeline(config)
         pipeline.execute()
         if args.output:
+            logger.info(f"Writing {args.output}")
             pipeline.write(args.output, overwrite=args.overwrite)
     except Exception as e:
-        print(e)
+        logger.exception(e)
         raise SystemExit(2) from e
 
     return(0)

skypy/pipeline/tests/data/test_config.yml

@@ -3,7 +3,7 @@ test_float: 1.0
 test_str: hello world
 test_func: !numpy.random.uniform
 test_func_with_arg: !len 'hello world'
-test_cosmology: !astropy.cosmology.FlatLambdaCDM
+cosmology: !astropy.cosmology.FlatLambdaCDM
   H0: 67.74
   Om0: 0.3075
 tables:

skypy/pipeline/tests/test_config.py

@@ -18,7 +18,7 @@ def test_load_skypy_yaml():
     assert isinstance(config['test_float'], float)
     assert isinstance(config['test_str'], str)
     assert isinstance(config['test_func'], Call)
-    assert isinstance(config['test_cosmology'], Call)
+    assert isinstance(config['cosmology'], Call)
     assert isinstance(config['tables']['test_table_1']['test_column_3'], Call)
 
     # Bad function

skypy/pipeline/tests/test_pipeline.py

@@ -215,7 +215,7 @@ def test_pipeline_read():
     assert isinstance(pipeline['test_int'], int)
     assert isinstance(pipeline['test_float'], float)
     assert isinstance(pipeline['test_str'], str)
-    assert isinstance(pipeline['test_cosmology'], Cosmology)
+    assert isinstance(pipeline['cosmology'], Cosmology)
     assert isinstance(pipeline['test_table_1'], Table)
     assert isinstance(pipeline['test_table_1']['test_column_3'], Column)
 

skypy/pipeline/tests/test_skypy.py

@@ -1,9 +1,12 @@
+from astropy.table import Table
 from astropy.utils.data import get_pkg_data_filename
 from contextlib import redirect_stdout
 from io import StringIO
 import os
 import pytest
 from skypy import __version__ as skypy_version
+from skypy.pipeline import load_skypy_yaml
+from skypy.pipeline._items import Call
 from skypy.pipeline.scripts import skypy
 
 
@@ -46,8 +49,60 @@ def test_skypy():
     assert e.value.code == 2
 
 
+def test_logging(capsys):
+
+    # Run skypy with default verbosity and check log is empty
+    filename = get_pkg_data_filename('data/test_config.yml')
+    output_file = 'logging.fits'
+    skypy.main([filename, output_file])
+    out, err = capsys.readouterr()
+    assert(not err)
+
+    # Run again with increased verbosity and capture log. Force an exception by
+    # not using the "--overwrite" flag when the output file already exists.
+    with pytest.raises(SystemExit):
+        skypy.main([filename, output_file, '--verbose'])
+    out, err = capsys.readouterr()
+
+    # Determine all DAG jobs and function calls from config
+    config = load_skypy_yaml(filename)
+    cosmology = config.pop('cosmology', None)
+    tables = config.pop('tables', {})
+    config.update({k: v.pop('.init', Call(Table)) for k, v in tables.items()})
+    columns = [f'{t}.{c}' for t, cols in tables.items() for c in cols]
+    functions = [f for f in config.values() if isinstance(f, Call)]
+    functions += [f for t, cols in tables.items() for f in cols.values() if isinstance(f, Call)]
+
+    # Check all jobs appear in the log
+    for job in list(config) + list(tables) + columns:
+        log_string = f"[INFO] skypy.pipeline: Generating {job}"
+        assert(log_string in err)
+
+    # Check all functions appear in the log
+    for f in functions:
+        log_string = f"[INFO] skypy.pipeline: Calling {f.function.__name__}"
+        assert(log_string in err)
+
+    # Check cosmology appears in the log
+    if cosmology:
+        assert("[INFO] skypy.pipeline: Setting cosmology" in err)
+
+    # Check writing output file is in the log
+    assert(f"[INFO] skypy: Writing {output_file}" in err)
+
+    # Check error for existing output file is in the log
+    assert(f"[ERROR] skypy: File '{output_file}' already exists." in err)
+
+    # Run again with decreased verbosity and check the log is empty
+    with pytest.raises(SystemExit):
+        skypy.main([filename, output_file, '-qq'])
+    out, err = capsys.readouterr()
+    assert(not err)
+
+
 def teardown_module(module):
 
     # Remove fits file generated in test_skypy
     os.remove('empty.fits')
+    os.remove('logging.fits')
     os.remove('test.fits')