Repository: CORE-GATECH-GROUP/serpent-tools (python)

Issue:
Determine and implement a way to test our message/logging systems
Working on the comparison feature, I realize we don't have a way to ensure that our logging system is actually logging what we want. This is more relevant for the testing the comparison utilities, and making sure that we are correctly notifying the user about the locations of differences.
For example, if we take two identical readers, read from the same file, then the comparison routine should print no bad messages and return `True`. To test more of the internals, we would start tweaking values, both by shape and by contents. Including and/or removing extra values, in the `resdata` dictionary, would further test the internals.

## Possible suggestions
1. Have our loggers work as a LIFO list, where we can stack additional loggers (primary being our existing logger, secondary being this testable variant) and utilize only the last value in the list for logging
1. Swapping out loggers during testing, e.g. in `setUpModule`, switch the logging system to one that captures and stores messages
1. Utilize a custom [`Handler` object](https://docs.python.org/3.6/library/logging.html#handler-objects) object that places messages in dictionaries
1. Subclass Logger and overwrite the [`makeRecord`](https://docs.python.org/3.6/library/logging.html#logging.Logger.makeRecord) method to store data on a dictionary as well

Pull request:
[DEV/TST] Add custom handler to capture and test logging
Closes #219 by including some new classes for suppressing and testing our logging. 

## Summary

* No more ERROR messages printed during testing
* New developer utilities for testing our logging capabilities

## Additional Logging capabilities

New `DictHandler` can be attached to a `logger`  and, instead of passing messages to the screen via standard out, the messages are captured in a dictionary by their level. This is done primarily by overwritting the [`emit`](https://docs.python.org/3.5/library/logging.html#logging.Handler.emit) method.

Added a few methods to add and remove these handlers from our module logger as well. This way, we can still utilize the various logging functions like `messages.error`.

## `serpentTools.tests.utils`

Created a utilities module to assist with testing. Currently contains a base mixin class `LoggerMixin` that is best used in the `TestCaseWithLogCapture` class. This latter class

1. Defines `setUp` method that clears out the handlers attached to the module logger and attaches the `DictHandler` for capturing messages
1. Defines a `tearDown` method that resets the module logger
1. Contains methods for checking if a message is entirely or partially contained in a specific log leve
1. Contains two `TestCase`-like methods, `assertMsgInLogs` and `assertMsgNotInLogs` to
easily check messages are stored in a manner we expect

For tests where we either manipulate the settings, which can cause some messages, or our samplers (they print messages for mismatched files), none of the logs are printed to the screen. Instead, they are captured and their existence is tested.

The primary benefit of this PR is that we can utilize this framework for further testing the comparison methods. Secondarily, all those additional comparison tests, which are by design fairly chatty, will not cloud up the terminal during `setup.py test`. Now, only failed tests and the usual test progression updates are printed to the screen. No more scary `ERROR` messages during testing, which did not instill confidence in the tests.

## Testing

A collection of tests were added to test the log capture and the test mixin objects as well.

## Documentation

Added documentation in the developer guide about the handler and the test utilities added in this PR

This is a fairly wide-ranging PR, so I'm not going to squash merge. Each commit has a fairly detailed message and is fairly contained. This is *eventually* the model we will move towards.

- [x] PR fits the [project scope](
http://serpent-tools.readthedocs.io/en/latest/develop/contributing.html#project-scope)
- [x] Code to be committed is [DRY](https://en.wikipedia.org/wiki/Don%27t_repeat_yourself) and matches the [code style](http://serpent-tools.readthedocs.io/en/latest/develop/codestyle.html#code-style) of the project
- [x] New and/or changed features are [well documented](http://serpent-tools.readthedocs.io/en/latest/develop/documentation.html#documentation) and have adequate testing

Patch:
diff --git a/docs/develop/logging.rst b/docs/develop/logging.rst
index 8f36e03..c5c061c 100644
--- a/docs/develop/logging.rst
+++ b/docs/develop/logging.rst
@@ -31,3 +31,10 @@ or removed in the future.
 
 .. autofunction:: serpentTools.messages.willChange
 
+
+Custom Handlers
+===============
+
+.. autoclass:: serpentTools.messages.DictHandler
+    :show-inheritance:
+    :no-inherited-members:
diff --git a/docs/develop/utils.rst b/docs/develop/utils.rst
index 848929c..6d251ab 100644
--- a/docs/develop/utils.rst
+++ b/docs/develop/utils.rst
@@ -8,3 +8,16 @@ Utilities
 .. automodule:: serpentTools.utils
     :members: convertVariableName, linkToWiki, str2vec, splitValsUnc
 
+
+.. _dev-testUtils:
+
+=================
+Testing Utilities
+=================
+
+.. autoclass:: serpentTools.tests.utils.LoggerMixin
+
+.. autoclass:: serpentTools.tests.utils.TestCaseWithLogCapture
+    :show-inheritance:
+    :no-inherited-members:
+    :members: setUp, tearDown, assertMsgInLogs, assertMsgNotInLogs
diff --git a/serpentTools/messages.py b/serpentTools/messages.py
index b040939..8ef4f26 100644
--- a/serpentTools/messages.py
+++ b/serpentTools/messages.py
@@ -10,6 +10,7 @@ See Also
 import functools
 import warnings
 import logging
+from logging import Handler
 from logging.config import dictConfig
 
 
@@ -27,6 +28,10 @@ class MismatchedContainersError(SamplerError):
     """Attempting to sample from dissimilar containers"""
     pass
 
+#
+# Logger options
+#
+
 
 LOG_OPTS = ['critical', 'error', 'warning', 'info', 'debug']
 
@@ -46,9 +51,12 @@ loggingConfig = {
             'stream': 'ext://sys.stdout'
         }
     },
-    'root': {
-        'handlers': ['console'],
-        'level': logging.WARNING
+    'loggers': {
+        'serpentTools': {
+            'handlers': ['console'],
+            'level': logging.WARNING,
+            'propagate': False,
+        },
     }
 }
 
@@ -57,6 +65,35 @@ dictConfig(loggingConfig)
 __logger__ = logging.getLogger('serpentTools')
 
 
+def addHandler(handler):
+    """
+    Add a handler to the logger
+
+    Parameters
+    ----------
+    handler: :class:`python.logging.Handler`
+        Subclass to handle the formatting and emitting
+        of log messages
+    """
+    if not issubclass(handler.__class__, Handler):
+        raise TypeError("Handler {} is of class {} and does not appear "
+                        "to be a subclass of {}"
+                        .format(handler, handler.__class__, Handler))
+    return __logger__.addHandler(handler)
+
+
+def removeHandler(handler):
+    """
+    Remove a handler from the internal logger
+
+    Parameters
+    ----------
+    handler: :class:`python.logging.Handler`
+        Handler to be removed
+    """
+    return __logger__.removeHandler(handler)
+
+
 def debug(message):
     """Log a debug message."""
     __logger__.debug('%s', message)
@@ -126,3 +163,44 @@ def _updateFilterAlert(msg, category):
     warnings.simplefilter('always', category)
     warnings.warn(msg, category=category, stacklevel=3)
     warnings.simplefilter('default', category)
+
+
+class DictHandler(Handler):
+    """
+    Handler that stores log messages in a dictionary
+
+    Attributes
+    ----------
+    logMessages: dict
+        Dictionary of lists where each key is a log level such
+        as ``'DEBUG'`` or ``'WARNING'``. The list associated
+        with each key contains all messages called under that
+        logging level
+    """
+    def __init__(self, level=logging.NOTSET):
+        Handler.__init__(self, level)
+        self.logMessages = {}
+
+    def flush(self):
+        """Clear the log messages dictionary"""
+        self.logMessages = {}
+
+    def close(self):
+        """Tidy up before removing from list of handlers"""
+        self.logMessages = {}
+        Handler.close(self)
+
+    def emit(self, record):
+        """
+        Store the message in the log messages by level.
+
+        Does no formatting to the record, simply stores
+        the message in :attr:`logMessages` dictionary
+        according to the records ``levelname``
+
+        Anticipates a :class:`logging.LogRecord` object
+        """
+        level = record.levelname
+        if level not in self.logMessages:
+            self.logMessages[level] = []
+        self.logMessages[level].append(record.getMessage())


Test patch:
diff --git a/serpentTools/tests/test_depSampler.py b/serpentTools/tests/test_depSampler.py
index 2ad166b..dcd2640 100644
--- a/serpentTools/tests/test_depSampler.py
+++ b/serpentTools/tests/test_depSampler.py
@@ -14,7 +14,7 @@ File Descriptions
 *. ``bwr_missingT`` is missing the final burnup step
 
 """
-import unittest
+from unittest import TestCase
 
 from six import iteritems
 from numpy import where, fabs, ndarray
@@ -25,21 +25,24 @@ from serpentTools.data import getFile
 from serpentTools.parsers.depletion import DepletionReader
 from serpentTools.samplers.depletion import DepletionSampler
 from serpentTools.tests import computeMeansErrors
+from serpentTools.tests.utils import TestCaseWithLogCapture
 
 _testFileNames = {'0', '1', 'badInventory', 'longT', 'missingT'}
 DEP_FILES = {key: getFile('bwr_{}_dep.m'.format(key))
              for key in _testFileNames}
 
 
-class DepletionSamplerFailTester(unittest.TestCase):
+class DepletionSamplerFailTester(TestCaseWithLogCapture):
 
     def test_badInventory(self):
         """Verify an error is raised for files with dissimilar isotopics"""
         self._mismatchedFiles(DEP_FILES['badInventory'])
+        self.assertMsgInLogs("ERROR", DEP_FILES['badInventory'], partial=True)
 
     def test_missingTimeSteps(self):
         """Verify an error is raised if length of time steps are dissimilar"""
         self._mismatchedFiles(DEP_FILES['missingT'])
+        self.assertMsgInLogs("ERROR", DEP_FILES['missingT'], partial=True)
 
     def _mismatchedFiles(self, badFilePath,
                          errorType=MismatchedContainersError):
@@ -48,7 +51,7 @@ class DepletionSamplerFailTester(unittest.TestCase):
             DepletionSampler(files)
 
 
-class DepletedSamplerTester(unittest.TestCase):
+class DepletedSamplerTester(TestCase):
     """
     Class that reads two similar files and validates the averaging
     and uncertainty propagation.
@@ -107,4 +110,5 @@ class DepletedSamplerTester(unittest.TestCase):
 
 
 if __name__ == '__main__':
-    unittest.main()
+    from unittest import main
+    main()
diff --git a/serpentTools/tests/test_detSampler.py b/serpentTools/tests/test_detSampler.py
index a49a4fe..bc3daaa 100644
--- a/serpentTools/tests/test_detSampler.py
+++ b/serpentTools/tests/test_detSampler.py
@@ -21,8 +21,6 @@ File Descriptions
     tolerance can still be achieved.
 
 """
-import unittest
-
 from six import iteritems
 
 from numpy import square, sqrt
@@ -32,6 +30,7 @@ from serpentTools.messages import MismatchedContainersError
 from serpentTools.data import getFile
 from serpentTools.parsers.detector import DetectorReader
 from serpentTools.samplers.detector import DetectorSampler
+from serpentTools.tests.utils import TestCaseWithLogCapture
 
 _DET_FILES = {
     'bwr0': 'bwr_0',
@@ -50,7 +49,7 @@ TOLERANCES = {
 }
 
 
-class DetSamplerTester(unittest.TestCase):
+class DetSamplerTester(TestCaseWithLogCapture):
     """
     Tester that looks for errors in mismatched detector files
     and validates the averaging and uncertainty propagation
@@ -70,6 +69,7 @@ class DetSamplerTester(unittest.TestCase):
 
     def setUp(self):
         self._checkContents()
+        TestCaseWithLogCapture.setUp(self)
 
     def test_properlyAveraged(self):
         """Validate the averaging for two unique detector files"""
@@ -90,12 +90,16 @@ class DetSamplerTester(unittest.TestCase):
         files = [getFile(fp)
                  for fp in ['bwr_0_det0.m', 'bwr_noxy_det0.m']]
         self._raisesMisMatchError(files)
+        self.assertMsgInLogs("ERROR", "detectors: Parser files", partial=True)
 
     def test_differentSizedDetectors(self):
         """Verify that an error is raised if detector shapes are different"""
         files = [getFile(fp)
                  for fp in ['bwr_0_det0.m', 'bwr_smallxy_det0.m']]
         self._raisesMisMatchError(files)
+        self.assertMsgInLogs(
+            "ERROR", "shape: Parser files",
+            partial=True)
 
     def _raisesMisMatchError(self, files):
         with self.assertRaises(MismatchedContainersError):
@@ -118,4 +122,5 @@ def _getExpectedAverages(d0, d1):
 
 
 if __name__ == '__main__':
-    unittest.main()
+    from unittest import main
+    main()
diff --git a/serpentTools/tests/test_messages.py b/serpentTools/tests/test_messages.py
new file mode 100644
index 0000000..fabd8e3
--- /dev/null
+++ b/serpentTools/tests/test_messages.py
@@ -0,0 +1,95 @@
+"""
+Test the logging and messaging functions
+"""
+
+from unittest import TestCase
+from warnings import catch_warnings
+
+from serpentTools.messages import (
+    deprecated, willChange,
+    addHandler, removeHandler,
+    __logger__,
+    debug, info, warning, error, critical,
+)
+from serpentTools.settings import rc
+from serpentTools.tests.utils import TestCaseWithLogCapture, LoggerMixin
+
+
+LOGGER_FUNCTIONS = [debug, info, warning, error, critical]
+
+
+class DecoratorTester(TestCase):
+    """Class to test the decorators for warnings."""
+
+    def test_futureDecorator(self):
+        """Verify that the future decorator doesn't break"""
+
+        @willChange('This function will be updated in the future, '
+                    'but will still exist')
+        def demoFuture(x, val=5):
+            return x + val
+
+        with catch_warnings(record=True) as record:
+            self.assertEqual(7, demoFuture(2))
+            self.assertEqual(7, demoFuture(2, 5))
+            self.assertEquals(len(record), 2,
+                              'Did not catch two warnings::willChange')
+
+    def test_deprecatedDecorator(self):
+        """Verify that the deprecated decorator doesn't break things"""
+
+        @deprecated('this nonexistent function')
+        def demoFunction(x, val=5):
+            return x + val
+
+        with catch_warnings(record=True) as record:
+            self.assertEqual(7, demoFunction(2))
+            self.assertEqual(7, demoFunction(2, 5))
+            self.assertEquals(len(record), 2,
+                              'Did not catch two warnings::deprecation')
+
+
+class LoggingTester(TestCaseWithLogCapture):
+    """
+    Class for testing various logging capabilities
+    """
+
+    def test_logger(self):
+        """Test the basic logging functions."""
+        searchMessage = "test_logger"
+        with rc:
+            rc['verbosity'] = 'debug'
+            for logFunc in LOGGER_FUNCTIONS:
+                funcLevel = logFunc.__name__.upper()
+                logFunc(searchMessage)
+                self.msgInLogs(funcLevel, searchMessage)
+
+    def test_addRemoveHandlers(self):
+        """Test that the add/remove handler functions work."""
+        with self.assertRaises(TypeError):
+            addHandler(1)
+        addHandler(self.handler)
+        self.assertIn(self.handler, __logger__.handlers,
+                      msg="addHandler did not add the handler")
+        removeHandler(self.handler)
+        self.assertNotIn(self.handler, __logger__.handlers,
+                         msg="removeHandler did not remove the handler")
+
+    def test_keyInLogs(self):
+        """Verify the behavrior of LoggerMixin.msgInLogs"""
+        message = "look for me"
+        warning(message)
+        self.assertMsgInLogs("WARNING", message)
+        self.assertMsgInLogs("WARNING", message[:5], partial=True)
+        self.assertMsgNotInLogs("WARNING", "<none>")
+        self.assertMsgNotInLogs("WARNING", "<none>", partial=True)
+        with self.assertRaises(KeyError):
+            self.msgInLogs("DEBUG", message)
+        with self.assertRaises(AttributeError):
+            newM = LoggerMixin()
+            newM.msgInLogs("WARNING", message)
+
+
+if __name__ == '__main__':
+    from unittest import main
+    main()
diff --git a/serpentTools/tests/test_settings.py b/serpentTools/tests/test_settings.py
index 00beffb..b4d60a2 100644
--- a/serpentTools/tests/test_settings.py
+++ b/serpentTools/tests/test_settings.py
@@ -1,16 +1,15 @@
 """Tests for the settings loaders."""
 from os import remove
-import warnings
-import unittest
+from unittest import TestCase
 
 import yaml
 import six
 
 from serpentTools import settings
-from serpentTools.messages import deprecated, willChange
+from serpentTools.tests.utils import TestCaseWithLogCapture
 
 
-class DefaultSettingsTester(unittest.TestCase):
+class DefaultSettingsTester(TestCase):
     """Class to test the functionality of the master loader."""
 
     @classmethod
@@ -34,7 +33,7 @@ class DefaultSettingsTester(unittest.TestCase):
         return self.defaultLoader[setting].default
 
 
-class RCTester(unittest.TestCase):
+class RCTester(TestCase):
     """Class to test the functionality of the scriptable settings manager."""
 
     @classmethod
@@ -107,7 +106,7 @@ class RCTester(unittest.TestCase):
         self.assertSetEqual(expected, actual)
 
 
-class ConfigLoaderTester(unittest.TestCase):
+class ConfigLoaderTester(TestCaseWithLogCapture):
     """Class to test loading multiple setttings at once, i.e. config files"""
 
     @classmethod
@@ -168,38 +167,9 @@ class ConfigLoaderTester(unittest.TestCase):
         badSettings.update(self.nestedSettings)
         self._writeTestRemoveConfFile(badSettings, self.files['nested'],
                                       self.configSettings, False)
-
-
-class MessagingTester(unittest.TestCase):
-    """Class to test the messaging framework."""
-
-    def test_futureDecorator(self):
-        """Verify that the future decorator doesn't break"""
-
-        @willChange('This function will be updated in the future, '
-                    'but will still exist')
-        def demoFuture(x, val=5):
-            return x + val
-
-        with warnings.catch_warnings(record=True) as record:
-            self.assertEqual(7, demoFuture(2))
-            self.assertEqual(7, demoFuture(2, 5))
-            self.assertEquals(len(record), 2,
-                              'Did not catch two warnings::willChange')
-
-    def test_depreciatedDecorator(self):
-        """Verify that the depreciated decorator doesn't break things"""
-
-        @deprecated('this nonexistent function')
-        def demoFunction(x, val=5):
-            return x + val
-
-        with warnings.catch_warnings(record=True) as record:
-            self.assertEqual(7, demoFunction(2))
-            self.assertEqual(7, demoFunction(2, 5))
-            self.assertEquals(len(record), 2,
-                              'Did not catch two warnings::deprecation')
+        self.assertMsgInLogs("ERROR", "bad setting", partial=True)
 
 
 if __name__ == '__main__':
-    unittest.main()
+    from unittest import main
+    main()
diff --git a/serpentTools/tests/utils.py b/serpentTools/tests/utils.py
new file mode 100644
index 0000000..69ee4d5
--- /dev/null
+++ b/serpentTools/tests/utils.py
@@ -0,0 +1,165 @@
+"""
+Utilities to make testing easier
+"""
+
+from unittest import TestCase
+from logging import NOTSET
+
+from serpentTools.messages import (
+    DictHandler, __logger__, removeHandler, addHandler,
+)
+
+
+class LoggerMixin(object):
+    """
+    Mixin class captures log messages
+
+    Attributes
+    ----------
+    handler: :class:`serpentTools.messages.DictHandler`
+        Logging handler that stores messages in a
+        :attr:`serpentTools.messages.DictHandler.logMessages`
+        dictionary according to level.
+    """
+    def __init__(self):
+        self.__old = []
+        self.handler = None
+
+    def attach(self, level=NOTSET):
+        """
+        Attach the :class:`serpentTools.messages.DictHandler`
+
+        Removes all :class:`logging.Handler` objects from the
+        old logger, and puts them back when :class:`detach` is
+        called
+
+        Parameters
+        ----------
+        level: int
+            Initial level to apply to handler
+        """
+        self.handler = DictHandler(level)
+        self.__old = __logger__.handlers
+        for handler in self.__old:
+            removeHandler(handler)
+        addHandler(self.handler)
+
+    def detach(self):
+        """Restore the original handers to the main logger"""
+        if self.handler is None:
+            raise AttributeError("Handler not set. Possibly not attached.")
+        removeHandler(self.handler)
+        for handler in self.__old:
+            addHandler(handler)
+        self.handler = None
+        self.__old = []
+
+    def msgInLogs(self, level, msg, partial=False):
+        """
+        Determine if the message is contained in the logs
+
+        Parameters
+        ----------
+        level: str
+            Level under which this message was posted.
+            Must be a key in the
+            :attr:`~serpentTools.messages.DictHandler.logMessages`
+            on the :attr:`handler` for this class
+        msg: str
+            Message to be found in the logs.
+        partial: bool
+            If this evaluates to true, then search through each
+            ``message`` in `logMessages` and return ``True`` if
+            ``msg in message``. Otherwise, look for exact matches
+
+        Returns
+        -------
+        bool:
+            If the message was found in the logs
+
+        Raises
+        ------
+        KeyError:
+            If the level was not found in the logs
+        AttributeError:
+            If the :attr:`handler` has not been created with :meth:`attach`
+        """
+        if self.handler is None:
+            raise AttributeError("Handler has not been attached. Must run "
+                                 "<attach> first")
+        logs = self.handler.logMessages
+        if level not in logs:
+            raise KeyError("Level {} not found in logs. Existing levels:\n{}"
+                           .format(level, list(sorted(logs.keys()))))
+        if not partial:
+            return msg in logs[level]
+        for message in logs[level]:
+            if msg in message:
+                return True
+        return False
+
+
+class TestCaseWithLogCapture(TestCase, LoggerMixin):
+    """
+    Lightly overwritten :class:`unittest.TestCase` that captures logs
+
+    Mix in the :class:`LoggerMixin` to automatically
+    :meth:`~LoggerMixin.attach` during
+    :meth:`~unittest.TestCase.setUp` and :meth:`~LoggerMixin.detach`
+    during :meth:`~unittest.TestCase.tearDown`
+
+    Intended to be subclassed for actual test methods
+    """
+
+    def __init__(self, *args, **kwargs):
+        TestCase.__init__(self, *args, **kwargs)
+        LoggerMixin.__init__(self)
+
+    def setUp(self):
+        """
+        Method to be called before every individual test.
+
+        Call :meth:`~serpentTools.tests.utils.LoggerMixin.attach`
+        to capture any log messages that would be presented during testing.
+        Should be called during any subclassing.
+        """
+        LoggerMixin.attach(self)
+
+    def tearDown(self):
+        """
+        Method to be called immediately after calling and recording test
+
+        Call :meth:`~serpentTools.tests.utils.LoggerMixin.detach`
+        to reset the module logger to its original state.
+        Should be called during any subclassing.
+        """
+        LoggerMixin.detach(self)
+
+    def _concatLogs(self, level):
+        logs = self.handler.logMessages.get(level, [])
+        return "\n- ".join([str(item) for item in logs])
+
+    def assertMsgInLogs(self, level, msg, partial=False):
+        """
+        Assert that the message was stored under a given level
+
+        Combines :meth:`LoggerMixin.msgInLogs` with
+        :meth:`unittest.TestCase.assertTrue`
+        """
+        matchType = "a partial" if partial else "an exact"
+        failMsg = "Could not find {} match for {} under {}\n{}".format(
+            matchType, msg, level, self._concatLogs(level))
+        self.assertTrue(self.msgInLogs(level, msg, partial),
+                        msg=failMsg)
+
+    def assertMsgNotInLogs(self, level, msg, partial=False):
+        """
+        Assert that the message was not stored under a given level
+
+        Combines :meth:`LoggerMixin.msgInLogs` with
+        :meth:`unittest.TestCase.assertFalse`
+        """
+        matchType = "a partial" if partial else "an exact"
+        failMsg = "Found {} match for {} under {} but should not have"
+        self.assertFalse(self.msgInLogs(level, msg, partial),
+                         msg=failMsg.format(matchType, msg, level))