Implement a custom DKISTLogger (#317)

* Implement a custom DKISTLogger

* Cleanup

* Some very basic tests

* more tests

dkist/__init__.py

@@ -1,19 +1,19 @@
 """
 The DKIST package aims to help you search, obtain and use DKIST data as part of your Python software.
 """
-from pkg_resources import DistributionNotFound, get_distribution
+from importlib.metadata import PackageNotFoundError
+from importlib.metadata import version as _version
 
-import astropy.config as _config
+from .logger import setup_default_dkist_logger as _setup_log
 
-from .dataset import Dataset, TiledDataset, load_dataset  # noqa
-from .utils.sysinfo import system_info  # noqa
+log = _setup_log(__name__)
 
 try:
-    __version__ = get_distribution(__name__).version
-except DistributionNotFound:
-    # package is not installed
+    __version__ = _version(__name__)
+except PackageNotFoundError:
     __version__ = "unknown"
 
+
 __all__ = ['TiledDataset', 'Dataset', 'load_dataset', 'system_info']
 
 
@@ -25,4 +25,10 @@ def write_default_config(overwrite=False):
     config file already exits this will write a config file appended with the
     version number, to facilitate comparison of changes.
     """
+    import astropy.config as _config
     return _config.create_config_file("dkist", "dkist", overwrite=overwrite)
+
+
+# Do internal imports last (so logger etc is initialised)
+from dkist.dataset import Dataset, TiledDataset, load_dataset  # noqa
+from dkist.utils.sysinfo import system_info  # noqa

dkist/conftest.py

@@ -16,14 +16,23 @@
 from astropy.time import Time
 from sunpy.coordinates.frames import Helioprojective
 
-from dkist import load_dataset
+from dkist import load_dataset, log
 from dkist.data.test import rootdir
 from dkist.dataset import Dataset
 from dkist.dataset.tiled_dataset import TiledDataset
 from dkist.io import FileManager
 from dkist.io.loaders import AstropyFITSLoader
 
 
+@pytest.fixture
+def caplog_dkist(caplog):
+    """
+    A `dkist.log` specifc equivalent to caplog.
+    """
+    log.addHandler(caplog.handler)
+    return caplog
+
+
 @pytest.fixture
 def array():
     shape = 2**np.random.randint(2, 7, size=2)

dkist/io/loaders.py

@@ -4,15 +4,14 @@
 """
 
 import abc
-import logging
 from pathlib import Path
 
 import numpy as np
 
 from astropy.io import fits
 from sunpy.util.decorators import add_common_docstring
 
-_LOGGER = logging.getLogger(__name__)
+from dkist import log
 
 __all__ = ['BaseFITSLoader', 'AstropyFITSLoader']
 
@@ -91,7 +90,7 @@ class AstropyFITSLoader(BaseFITSLoader):
 
     def __getitem__(self, slc):
         if not self.absolute_uri.exists():
-            _LOGGER.debug("File %s does not exist.", self.absolute_uri)
+            log.debug("File %s does not exist.", self.absolute_uri)
             # Use np.broadcast_to to generate an array of the correct size, but
             # which only uses memory for one value.
             return np.broadcast_to(np.nan, self.shape) * np.nan
@@ -100,7 +99,7 @@ def __getitem__(self, slc):
                        memmap=False,  # memmap is redundant with dask and delayed loading
                        do_not_scale_image_data=True,  # don't scale as we shouldn't need to
                        mode="denywrite") as hdul:
-            _LOGGER.debug("Accessing slice %s from file %s", slc, self.absolute_uri)
+            log.debug("Accessing slice %s from file %s", slc, self.absolute_uri)
 
             hdu = hdul[self.target]
             if hasattr(hdu, "section"):

dkist/logger.py

@@ -0,0 +1,118 @@
+"""
+This module contains helpers to use the Python logger to show messages to users.
+
+It is heavily insipired by Astropy's logger, but implemented independantly
+because Astropy warn you against directly using theirs.
+
+This module sets up the following things:
+
+* A `logging.Logger` subclass which:
+  - Tracks the module which triggered the log call.
+  - Overrides warnings.showwarnings so that subclasses of given warning classes are displayed using the logger.
+* Sets up a ``log`` instance which uses the Astropy StreamHandler class to log to stdout and colourise the output.
+"""
+import os
+import sys
+import logging
+import warnings
+
+from astropy.logger import StreamHandler as AstropyStreamHandler
+from astropy.utils.introspection import find_current_module
+
+from dkist.utils.exceptions import DKISTWarning
+
+
+class DKISTLogger(logging.Logger):
+    """
+    A knock off AstropyLogger.
+    """
+    _showwarning_orig = None
+
+    def __init__(self, name, level=logging.NOTSET, *, capture_warning_classes=None):
+        super().__init__(name, level=level)
+        self.capture_warning_classes = tuple(capture_warning_classes) if capture_warning_classes is not None else tuple()
+
+        self.enable_warnings_capture()
+
+    def enable_warnings_capture(self):
+        if self._showwarning_orig is None:
+            self._showwarning_orig = warnings.showwarning
+            warnings.showwarning = self._showwarning
+
+    def disable_warnings_capture(self):
+        if self._showwarning_orig is not None:
+            warnings.showwarning = self._showwarning_orig
+            self._showwarning_orig = None
+
+    def makeRecord(
+        self,
+        name,
+        level,
+        pathname,
+        lineno,
+        msg,
+        args,
+        exc_info,
+        func=None,
+        extra=None,
+        sinfo=None,
+    ):
+        if extra is None:
+            extra = {}
+
+        if "origin" not in extra:
+            current_module = find_current_module(1, finddiff=[True, "logging"])
+            if current_module is not None:
+                extra["origin"] = current_module.__name__
+            else:
+                extra["origin"] = "unknown"
+
+        return super().makeRecord(
+            name,
+            level,
+            pathname,
+            lineno,
+            msg,
+            args,
+            exc_info,
+            func=func,
+            extra=extra,
+            sinfo=sinfo,
+        )
+
+    def _showwarning(self, *args, **kwargs):
+        # Bail out if we are not catching a warning from one of the given
+        # classes (or subclasses)
+        if not isinstance(args[0], self.capture_warning_classes):
+            return self._showwarning_orig(*args, **kwargs)
+
+        warning = args[0]
+        message = f"{warning.__class__.__name__}: {args[0]}"
+
+        mod_path = args[2]
+        # Now that we have the module's path, we look through sys.modules to
+        # find the module object and thus the fully-package-specified module
+        # name.  The module.__file__ is the original source file name.
+        mod_name = None
+        mod_path, ext = os.path.splitext(mod_path)
+        for name, mod in list(sys.modules.items()):
+            try:
+                # Believe it or not this can fail in some cases:
+                # https://github.com/astropy/astropy/issues/2671
+                path = os.path.splitext(getattr(mod, "__file__", ""))[0]
+            except Exception:
+                continue
+            if path == mod_path:
+                mod_name = mod.__name__
+                break
+
+        if mod_name is not None:
+            self.warning(message, extra={"origin": mod_name})
+        else:
+            self.warning(message)
+
+
+def setup_default_dkist_logger(name):
+    log = DKISTLogger(name, level=logging.INFO, capture_warning_classes=[DKISTWarning])
+    log.addHandler(AstropyStreamHandler())
+    return log

dkist/tests/test_logger.py

@@ -0,0 +1,95 @@
+import logging
+import warnings
+
+import pytest
+
+from dkist import log
+from dkist.utils.exceptions import DKISTUserWarning, DKISTWarning
+
+
+def test_debug_log(caplog_dkist):
+    # By default the level is set to INFO so we shouldn't get anything here.
+    log.debug("test_debug_log")
+    assert caplog_dkist.record_tuples == []
+
+
+def test_info_log(caplog_dkist, capsys):
+    log.info("test_info_log")
+    assert caplog_dkist.record_tuples == [("dkist", logging.INFO, "test_info_log")]
+
+    captured = capsys.readouterr()
+    assert "INFO: test_info_log [dkist.tests.test_logger]" in captured.out
+
+
+def test_warning_log(caplog_dkist, capsys):
+    log.warning("test_warning_log")
+
+    assert caplog_dkist.record_tuples == [("dkist", logging.WARNING, "test_warning_log")]
+    captured = capsys.readouterr()
+    assert "WARNING: test_warning_log [dkist.tests.test_logger]" in captured.err
+
+
+def test_error_log(caplog_dkist, capsys):
+    log.error("test_error_log")
+
+    assert caplog_dkist.record_tuples == [("dkist", logging.ERROR, "test_error_log")]
+    captured = capsys.readouterr()
+    assert "ERROR: test_error_log [dkist.tests.test_logger]" in captured.err
+
+
+def test_warning_capture(caplog_dkist, capsys):
+    log.disable_warnings_capture()
+    log.enable_warnings_capture()
+
+    with warnings.catch_warnings():
+        warnings.simplefilter("always")
+        warnings.warn("Test warning", DKISTWarning)
+        assert caplog_dkist.record_tuples == [("dkist", logging.WARNING, "DKISTWarning: Test warning")]
+
+    captured = capsys.readouterr()
+    assert "WARNING: DKISTWarning: Test warning [dkist.tests.test_logger]" in captured.err
+
+
+def test_subclass_warning_capture(caplog_dkist, capsys):
+    log.disable_warnings_capture()
+    log.enable_warnings_capture()
+
+    with warnings.catch_warnings():
+        warnings.simplefilter("always")
+        warnings.warn("Test warning", DKISTUserWarning)
+        assert caplog_dkist.record_tuples == [("dkist", logging.WARNING, "DKISTUserWarning: Test warning")]
+
+    captured = capsys.readouterr()
+    assert "WARNING: DKISTUserWarning: Test warning [dkist.tests.test_logger]" in captured.err
+
+
+def test_no_warning_capture(caplog_dkist, capsys):
+    log.disable_warnings_capture()
+
+    with pytest.warns(match="Test warning"):
+        with warnings.catch_warnings():
+            # To ensure that disable works, we enable it and then disable it
+            # again after pytest is done with all it's stuff
+            log.enable_warnings_capture()
+            log.disable_warnings_capture()
+            warnings.simplefilter("always")
+            warnings.warn("Test warning", DKISTWarning)
+            assert caplog_dkist.record_tuples == []
+
+    captured = capsys.readouterr()
+    assert captured.err == ""
+
+
+def test_not_class_warning_capture(caplog_dkist, capsys):
+    log.disable_warnings_capture()
+
+    with pytest.warns(match="Test warning"):
+        with warnings.catch_warnings():
+            # We must re-enable capture in the context manager
+            log.enable_warnings_capture()
+            warnings.simplefilter("always")
+            warnings.warn("Test warning", Warning)
+            assert caplog_dkist.record_tuples == []
+
+    captured = capsys.readouterr()
+    assert captured.err == ""

dkist/utils/exceptions.py

@@ -1,2 +1,16 @@
-class DKISTDeprecationWarning(DeprecationWarning):
-    pass
+class DKISTWarning(Warning):
+    """
+    The base warning class from which all dkist warnings should inherit.
+    """
+
+class DKISTUserWarning(UserWarning, DKISTWarning):
+    """
+    The primary warning class for dkist.
+
+    Use this if you do not need a specific type of warning.
+    """
+
+class DKISTDeprecationWarning(DeprecationWarning, DKISTWarning):
+    """
+    A warning class to use when functionality will be changed or removed in a future version.
+    """