SAR-54 Add initial implementation and docs

CHANGELOG.rst

@@ -5,10 +5,10 @@ Change Log
 All notable changes to this project will be documented in this file.
 This project adheres to `Semantic Versioning <http://semver.org/>`_.
 
-[Unreleased]
-************
+v0.1.0
+******
 
 Added
 -----
 
-* Empty Python project directory structure
+* First release of the Python package.

LICENSE

@@ -14,7 +14,7 @@ are permitted provided that the following conditions are met:
   list of conditions and the following disclaimer in the documentation and/or
   other materials provided with the distribution.
 
-* Neither the name of SKA Skeleton nor the names of its
+* Neither the name of SKA Logger nor the names of its
   contributors may be used to endorse or promote products derived from this
   software without specific prior written permission.
 

Makefile

@@ -11,8 +11,9 @@ all: test lint
 # then be extracted to form the CI summary for the test procedure.
 test:
 
-	 python setup.py test | tee ./build/setup_py_test.stdout; \
-	 mv coverage.xml ./build/reports/code-coverage.xml;
+	mkdir -p build && \
+	python setup.py test | tee ./build/setup_py_test.stdout && \
+	mv coverage.xml ./build/reports/code-coverage.xml
 
 # The following steps copy across useful output to this volume which can
 # then be extracted to form the CI summary for the test procedure.
@@ -20,8 +21,8 @@ lint:
 
 	# FIXME pylint needs to run twice since there is no way go gather the text and junit xml output at the same time
 	pip3 install pylint2junit; \
-	pylint --output-format=parseable ska_python_skeleton | tee ./build/code_analysis.stdout; \
-	pylint --output-format=pylint2junit.JunitReporter ska_python_skeleton > ./build/reports/linting.xml;
+	pylint --output-format=parseable ska_logging | tee ./build/code_analysis.stdout; \
+	pylint --output-format=pylint2junit.JunitReporter ska_logging > ./build/reports/linting.xml;
 
 
 .PHONY: all test lint

README.md

-SKA Python Skeleton Project
-===========================
+SKA Logging Configuration
+=========================
 
-[![Documentation Status](https://readthedocs.org/projects/ska-python-skeleton/badge/?version=latest)](https://developer.skatelescope.org/projects/skeleton/en/latest/?badge=latest)
+[![Documentation Status](https://readthedocs.org/projects/ska-logging/badge/?version=latest)](https://developer.skatelescope.org/projects/ska-logging/en/latest/?badge=latest)
 
-Briefly describe your project here
+This project allows standard logging configuration across all SKA projects.  The format used is described in detail
+on the [developer portal](https://developer.skatelescope.org/en/latest/development/logging-format.html).
+
+This library should be used to configure the application's logging system as early as possible at start up.
+Note that for Python TANGO devices that inherit from [SKABaseDevice](https://gitlab.com/ska-telescope/lmc-base-classes/blob/master/skabase/SKABaseDevice/SKABaseDevice.py),
+this is already done in the base class, so it does not need to be done again.
+
+Usage
+-----
+
+For Python applications, this is as simple as:
+
+```python
+import logging
+from ska_logging import configure_logging
+
+def main():
+    configure_logging()
+    logger = logging.getLogger("ska.example")
+    logger.info("Logging started for Example application")
+```
+The `configure_logging` function takes additional arguments, including one that allows the initial log level to
+be specified.  It may be useful to link that to a command line option or environment variable.
+
+```python
+import logging
+from ska_logging import configure_logging
+
+def main():
+    configure_logging(logging.DEBUG)
+```
+
+SKA's logging format allows for simple tags (key-value pairs) to be included in log messages.  Application-specific
+behaviour can be provided via a filter, which will be added to all handlers in the configuration used
+by `configure_logging`.  If this filter is provided, it must add a `tags` attribute to each record, as the log
+message formatting string will include a `%(tags)s` field.
+
+Note that the logging format limits the characters allowed in tags.  For example, `|` is not allowed.
+No validation is done by this library.  If the filter is `None` (the default), then the field will be omitted.
+
+```python
+import logging
+from ska_logging import configure_logging
+
+
+class TangoDeviceTagsFilter(logging.Filter):
+    def filter(self, record):
+        record.tags = "tango-device:my/tango/device"
+        return True
+
+def main():
+    configure_logging(level="DEBUG", tags_filter=TangoDeviceTagsFilter)
+```
+
+In the more general case, the configuration can be updated with an additional dict, matching
+the `logging.config.dictConfig`
+[schema](https://docs.python.org/3/library/logging.config.html#dictionary-schema-details).
+This additional dict is recursively merged with the default configuration.  While not recommended, keys in the
+default configuration can be removed by setting the corresponding override key's value to `None`.   In the
+example below, we add output to a file.  Note that the `"default"` formatter and `"console"` handler are provided
+by the default configuration.
+
+```python
+import logging.handlers
+from ska_logging import configure_logging
+
+
+ADDITIONAL_LOGGING_CONFIG = {
+    "handlers": {
+        "file": {
+            "()" : logging.handlers.RotatingFileHandler,
+            "formatter": "default",
+            "filename": "./ska.example.log",
+            "maxBytes": 2048,
+            "backupCount": 2,
+        }
+    },
+    "root": {
+        "handlers": ["console", "file"],
+    }
+}
+
+def main():
+    configure_logging(overrides=ADDITIONAL_LOGGING_CONFIG)
+```
+
+By default, calls to `configure_logging` do not disable existing non-root loggers.  This allows
+multiple calls to the function, although that will generally not be required.  This behaviour can be
+overridden using the `"disable_existing_loggers"` key.
 
 Requirements
 ------------
@@ -59,11 +147,11 @@ Testing
  * Use [Pylint](https://www.pylint.org) as the code analysis framework
  * By default it uses the [PEP8 style guide](https://www.python.org/dev/peps/pep-0008/)
  * Use the provided `code-analysis.sh` script in order to run the code analysis in the `module` and `tests`
- * Code analysis should be run by calling `pylint ska_python_skeleton`. All pertaining options reside under the `.pylintrc` file.
+ * Code analysis should be run by calling `pylint ska_logging`. All pertaining options reside under the `.pylintrc` file.
  * Code analysis should only raise document related warnings (i.e. `#FIXME` comments) before merging the code
 
 Writing documentation
- --------------------
+---------------------
  * The documentation generator for this project is derived from SKA's [SKA Developer Portal repository](https://github.com/ska-telescope/developer.skatelescope.org)
  * The documentation can be edited under `./docs/src`
  * If you want to include only your README.md file, create a symbolic link inside the `./docs/src` directory if the existing one does not work:

docs/src/index.rst

@@ -30,14 +30,14 @@
 
 .. toctree::
   :maxdepth: 2
-  :caption: Package-name
+  :caption: SKA logging configuration
   :hidden:
 
   package/guide
 
 
-Project-name documentation
-==========================
+SKA logging configuration documentation
+=======================================
 
 These are all the packages, functions and scripts that form part of the project.
 

docs/src/package/guide.rst

@@ -4,16 +4,16 @@
 .. todo::
     - Insert todo's here
 
-**************************
-Package-name documentation
-**************************
+*****************
+API documentation
+*****************
 
-This section describes requirements and guidelines.
+This section details the public API for configuring application logging across the SKA project.
 
-Subtitle
-========
+Python
+======
 
-Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat. Duis aute irure dolor in reprehenderit in voluptate velit esse cillum dolore eu fugiat nulla pariatur. Excepteur sint occaecat cupidatat non proident, sunt in culpa qui officia deserunt mollit anim id est laborum.
+The API for the configuration using Python is shown below.
 
 .. Automatic API Documentation section. Generating the API from the docstrings. Modify / change the directory structure as you like
 
@@ -22,11 +22,5 @@ Public API Documentation
 Functions
 ---------
 
-.. automodule:: ska_python_skeleton.ska_python_skeleton
-    :members:
-
-Classes
--------
-.. autoclass:: ska_python_skeleton.ska_python_skeleton.SKA
-    :noindex:
+.. automodule:: ska_logging
     :members:

setup.cfg

@@ -7,11 +7,12 @@ test=pytest
 
 [coverage:run]
 branch = True
-source = ska_python_skeleton
+source = ska_logging
 
 [tool:pytest]
 testpaths = tests
 addopts = --cov --json-report --json-report-file=htmlcov/report.json --cov-report term --cov-report html --cov-report xml --pylint --pylint-error-types=EF --junitxml=./build/reports/unit-tests.xml
+junit_family = legacy
 
 # Define `python setup.py build_sphinx`
 [build_sphinx]

setup.py

@@ -7,18 +7,18 @@ with open('README.md') as readme_file:
     readme = readme_file.read()
 
 setup(
-    name='ska_python_skeleton',
-    version='0.0.0',
+    name='ska_logging',
+    version='0.1.0',
     description="",
     long_description=readme + '\n\n',
-    author="Your Name",
-    author_email='your.email@mail.com',
-    url='https://github.com/ska-telescope/ska-python-skeleton',
+    author='Anton Joubert',
+    author_email='ajoubert+ska@ska.ac.za',
+    url='https://gitlab.com/ska-telescope/ska-logging',
     packages=[
-        'ska_python_skeleton',
+        'ska_logging',
     ],
-    package_dir={'ska_python_skeleton':
-                 'ska_python_skeleton'},
+    package_dir={'ska_logging':
+                 'ska_logging'},
     include_package_data=True,
     license="BSD license",
     zip_safe=False,
@@ -28,12 +28,14 @@ setup(
         'License :: OSI Approved :: BSD License',
         'Natural Language :: English',
         'Programming Language :: Python :: 3',
-        'Programming Language :: Python :: 3.4',
         'Programming Language :: Python :: 3.5',
         'Programming Language :: Python :: 3.6',
+        'Programming Language :: Python :: 3.7',
+        'Programming Language :: Python :: 3.8',
     ],
+    python_requires='>=3.5',
     test_suite='tests',
-    install_requires=[],  # FIXME: add your package's dependencies to this list
+    install_requires=[],
     setup_requires=[
         # dependency for `python setup.py test`
         'pytest-runner',

ska_logging/__init__.py

+# -*- coding: utf-8 -*-
+
+"""Module init code."""
+
+__all__ = (
+    'configure_logging',
+)
+__version__ = '0.1.0'
+__author__ = 'Anton Joubert'
+__email__ = 'ajoubert+ska@ska.ac.za'
+
+
+from .configuration import configure_logging

ska_logging/configuration.py

+# -*- coding: utf-8 -*-
+
+"""This module provides the standard logging configuration."""
+import copy
+import logging
+import logging.config
+import time
+
+
+class _UTCFormatter(logging.Formatter):
+    converter = time.gmtime
+
+
+# Format defined here:
+#   https://developer.skatelescope.org/en/latest/development/logging-format.html
+# VERSION "|" TIMESTAMP "|" SEVERITY "|" [THREAD-ID] "|" [FUNCTION] "|" [LINE-LOC] "|"
+#  [TAGS] "|" MESSAGE LF
+
+_FORMAT_STR_NO_TAGS = (
+    "1|"
+    "%(asctime)s.%(msecs)03dZ|"
+    "%(levelname)s|"
+    "%(threadName)s|"
+    "%(funcName)s|"
+    "%(filename)s#%(lineno)d|"
+    "|"
+    "%(message)s"
+)
+
+_FORMAT_STR_WITH_TAGS = (
+    "1|"
+    "%(asctime)s.%(msecs)03dZ|"
+    "%(levelname)s|"
+    "%(threadName)s|"
+    "%(funcName)s|"
+    "%(filename)s#%(lineno)d|"
+    "%(tags)s|"
+    "%(message)s"
+)
+
+_LOGGING_CONFIG = {
+    "version": 1,
+    "disable_existing_loggers": False,
+    "formatters": {
+        "default": {
+            '()': _UTCFormatter,
+            "format": _FORMAT_STR_NO_TAGS,
+            "datefmt": "%Y-%m-%dT%H:%M:%S",
+        },
+    },
+    "handlers": {
+        "console": {
+            "class": "logging.StreamHandler",
+            "formatter": "default",
+            "stream": "ext://sys.stdout",
+        },
+    },
+    "root": {
+        "handlers": ["console"],
+        "filters": [],
+        "level": "INFO",
+    }
+}
+
+
+def configure_logging(level=None, tags_filter=None, overrides=None):
+    """Configure Python logging for SKA applications.
+
+    This function should be used to configure the application's logging
+    system as early as possible at start up.
+
+    .. note::  For Python TANGO devices that inherit from `lmcbaseclasses.SKABaseDevice`
+               this is already done in that base class, so it does not need to be done again.
+
+    Example usage is shown in this repo's ``README.md`` file.
+
+    Parameters
+    ----------
+
+    level : str or int, optional
+        Set the logging level to this instead of the default.  Use the string representations
+        like ""INFO" and "DEBUG", or integer values like `logging.INFO` and `logging.DEBUG`.
+    tags_filter : type derived from `logging.Filter`, optional
+        If this type (not instance) is provided, the default formatter will include a
+        "%(tags)s" specifier.  The filter must inject the `tags` attribute in each
+        record.
+    overrides : dict, optional
+        The default logging configuration can be modified by passing in this
+        dict.  It will be recursively merged with the default.  This allows
+        existing values to be modified, or even removed.  It also allows additional
+        loggers, handlers, filters and formatters to be added.  See the `_override`
+        function for more details on the merging process.  The end result must
+        be compatible with the `logging.config.dictConfig` schema.
+        Note that the `level` and `tags_filter` parameter are applied after
+        merging the overrides.
+
+    """
+    config = copy.deepcopy(_LOGGING_CONFIG)
+    if overrides:
+        config = _override(config, overrides)
+    if level:
+        config["root"]["level"] = level
+    if tags_filter:
+        config["filters"] = {
+            "tags": {
+                "()": tags_filter,
+            }
+        }
+        for handler in config["handlers"].values():
+            filters = handler.get("filters", [])
+            if "tags" not in filters:
+                filters.append("tags")
+            handler["filters"] = filters
+        config["formatters"]["default"]["format"] = _FORMAT_STR_WITH_TAGS
+    logging.config.dictConfig(config)
+
+
+def _override(config, overrides):
+    """Update a config dictionary with overrides, merging dictionaries.
+
+    Where both sides have a dictionary, the override is done recursively.
+    Where `overrides` contains a value of `None`, the corresponding entry is
+    deleted from the return value.
+    .. note:: this does not validate the result, which should be done by the caller.
+
+    Code based on:
+        https://github.com/ska-sa/katsdpcontroller/blob/
+        5d988d2a7a00921924739bba1ec3f6a7d6293eae/katsdpcontroller/product_config.py#L91
+
+        Copyright (c) 2013-2019, National Research Foundation (SARAO)
+        All rights reserved.
+        (BSD-3-Clause license)
+
+    Parameters
+    ----------
+    config : dict
+        The input configuration dictionary.
+    overrides : dict
+        The dictionary which will be used to override the original configuration.
+
+    Returns
+    -------
+    dict
+        The updated configuration.
+
+    """
+    if isinstance(config, dict) and isinstance(overrides, dict):
+        new_config = dict(config)
+        for key, value in overrides.items():
+            if value is None:
+                new_config.pop(key, None)
+            else:
+                new_config[key] = _override(config.get(key), value)
+        return new_config
+    return overrides

tests/__init__.py

+# -*- coding: utf-8 -*-

tests/test_configuration.py

+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+
+"""Tests for the ska_logging module."""
+import logging
+import logging.handlers
+import time
+import pytest
+
+import ska_logging.configuration
+
+from ska_logging import configure_logging
+
+
+@pytest.fixture
+def reset_logging():
+    """Cleanup logging module's state after each test (at least try to)."""
+    yield
+    manager = logging.root.manager
+    manager.disabled = logging.NOTSET
+    for logger in list(manager.loggerDict.values()) + [logging.root]:
+        if isinstance(logger, logging.Logger):
+            logger.setLevel(logging.NOTSET)
+            logger.propagate = True
+            logger.disabled = False
+            logger.filters.clear()
+            handlers = logger.handlers.copy()
+            for handler in handlers:
+                # Copied from `logging.shutdown`.
+                try:
+                    handler.acquire()
+                    handler.flush()
+                    handler.close()
+                except (OSError, ValueError):
+                    pass
+                finally:
+                    handler.release()
+                logger.removeHandler(handler)
+
+
+def get_named_handler(logger, name):
+    """Search up through logger hierarchy to find a handler with the specified name."""
+    while logger:
+        for handler in logger.handlers:
+            if handler.name == name:
+                return handler
+        logger = logger.parent
+
+
+class AppendHandler(logging.Handler):
+    """Handler that keeps a history of the records and formatted log messages."""
+
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        self.logs = []
+        self.records = []
+
+    def emit(self, record):
+        self.records.append(record)
+        self.logs.append(self.format(record))
+
+
+"""Override configuration for recording loggers"""
+RECORDER_OVERRIDES = {
+    "handlers": {
+        "recorder": {
+            "()": AppendHandler,
+            "formatter": "default",
+        }
+    },
+    "root": {
+        "handlers": ["console", "recorder"],
+    }
+}
+
+@pytest.mark.usefixtures("reset_logging")
+class TestConfigureLogging:
+    """Tests for :func:`~ska_logging.configuration.configure_logging`."""
+
+    @pytest.fixture
+    def default_logger(self):
+        """Return user logger instance with default configuration."""
+        configure_logging()
+        yield logging.getLogger("ska.test.app")
+
+    @pytest.fixture
+    def recording_logger(self):
+        """Return user logger, including a recording handler.
+
+        The additional handler has the name "recorder".  It uses the default formatter,
+        and stores all formatted output strings as a list in its `logs` attribute.
+        It also keeps a list of the raw log records in its `records` attribute.
+
+        Note:  we use this instead of pytest's `caplog` fixture because we cannot change
+        the formatter that it uses.
+        """
+        configure_logging(overrides=RECORDER_OVERRIDES)
+        yield logging.getLogger("ska.logger")
+
+    @pytest.fixture
+    def recording_tags_logger(self):
+        """Return user logger like :func:`recording_logger`, but including tags filter."""
+        class MyFilter(logging.Filter):
+            def filter(self, record):
+                record.tags = "key1:value1,key2:value2"
+                return True
+
+        configure_logging(tags_filter=MyFilter, overrides=RECORDER_OVERRIDES)
+        yield logging.getLogger("ska.logger")
+
+    def test_configure_logging_includes_console_handler(self, default_logger):
+        assert get_named_handler(default_logger, "console")
+
+    def test_configure_logging_multiple_calls_non_root_logger_still_enabled(self, default_logger):
+        logger = logging.getLogger("ska.logger.test")
+        assert not logger.disabled
+        configure_logging()
+        assert not logger.disabled
+
+    def test_configure_logging_default_log_level_info(self, default_logger):
+        logger = logging.getLogger("ska.logger.test")
+        assert logger.getEffectiveLevel() == logging.INFO
+        assert default_logger.getEffectiveLevel() == logging.INFO
+
+    def test_configure_logging_set_log_level_int(self):
+        configure_logging(level=logging.DEBUG)
+        logger = logging.getLogger('ska.logger.test')
+        assert logger.getEffectiveLevel() == logging.DEBUG
+
+    def test_configure_logging_set_log_level_string(self):
+        configure_logging(level="WARNING")
+        logger = logging.getLogger('ska.logger.test')
+        assert logger.getEffectiveLevel() == logging.WARNING
+
+    def test_configure_logging_default_uses_utc_time(self, recording_logger):
+        recording_logger.info("UTC message")
+        recorder = get_named_handler(recording_logger, "recorder")
+        record = recorder.records[0]
+        log_message = recorder.logs[0]
+        expected_time = time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(record.created))
+        assert "UTC message" in log_message
+        assert expected_time in log_message  # just testing UTC, so ignore the milliseconds part
+
+    def test_configure_logging_default_no_tags(self, default_logger):
+        handler = get_named_handler(default_logger, "console")
+        formatter = handler.formatter
+        assert "%(tag)s" not in formatter._fmt
+
+    def test_configure_logging_tags_filter_adds_tags_field(self, recording_tags_logger):
+        handler = get_named_handler(recording_tags_logger, "console")
+        formatter = handler.formatter
+        assert "%(tags)s" in formatter._fmt
+
+    def test_configure_logging_tags_filter_emits_tags_value(self, recording_tags_logger):
+        recording_tags_logger.info('Tags message')
+        recorder = get_named_handler(recording_tags_logger, "recorder")
+        record = recorder.records[0]
+        log_message = recorder.logs[0]
+        assert record.tags == "key1:value1,key2:value2"
+        assert log_message.endswith("|key1:value1,key2:value2|Tags message")
+
+    def test_configure_logging_override(self):
+        overrides = {
+            "handlers": {
+                "test": {
+                    "class": "logging.StreamHandler",
+                    "formatter": "default",
+                }
+            },
+            "root": {
+                "handlers": ["console", "test"],
+            }
+        }
+        configure_logging(overrides=overrides)
+        logger = logging.getLogger()
+        assert get_named_handler(logger, "console")
+        assert get_named_handler(logger, "test")
+
+
+class TestOverride:
+    """Tests for :func:`~ska_logging.configuration._override`.
+
+    Code based on:
+        https://github.com/ska-sa/katsdpcontroller/blob/
+        40ec9ae57adf1d441fc42b5c6eac86aa57b6e3aa/katsdpcontroller/test/test_product_config.py#L42
+
+        Copyright (c) 2013-2019, National Research Foundation (SARAO)
+        All rights reserved.
+        (BSD-3-Clause license)
+    """
+
+    def test_add(self):
+        out = ska_logging.configuration._override({"a": 1}, {"b": 2})
+        assert out == {"a": 1, "b": 2}
+
+    def test_remove(self):
+        out = ska_logging.configuration._override({"a": 1, "b": 2}, {"b": None})
+        assert out == {"a": 1}
+        out = ska_logging.configuration._override(out, {"b": None})  # Already absent
+        assert out == {"a": 1}
+
+    def test_replace(self):
+        out = ska_logging.configuration._override({"a": 1, "b": 2}, {"b": 3})
+        assert out == {"a": 1, "b": 3}
+
+    def test_recurse(self):
+        orig = {"a": {"aa": 1, "ab": 2}, "b": {"ba": {"c": 10}, "bb": [5]}}
+        override = {"a": {"aa": [], "ab": None, "ac": 3}, "b": {"bb": [1, 2]}}
+        out = ska_logging.configuration._override(orig, override)
+        assert out == {"a": {"aa": [], "ac": 3}, "b": {"ba": {"c": 10}, "bb": [1, 2]}}