Merge lp:~thomir-deactivatedaccount/uservice-utils/trunk-add-logging-decorator into lp:uservice-utils

[Thomi Richards]

Add the ExtraLogger class.

Add the ExtraLogger class, which helps us by not having to pass 'extra=extra' everywhere.

[Joe Talbott (joetalbott)]

Some in-line comments. Everything appears functionally correct.

[Celso Providelo (cprov)]

Thomi,

It looks very good!

As discussed on IRC, most of our workers use-case will involve calling set_extra_args() in the beginning of the initialisation with the 'default' extra logging keys (solution, service and hostname) and the call set_extra_args() again with the received message payload repeatedly on 'worker.on_message_cb'.

Since set_extra_args() overrides the logging "extra" dict, it won't erroneously mask invalid/incomplete payloads, in contrast to logger.info('', extra=payload), the latter should be blocked on reviews.

review: Approve

[lp:~thomir-deactivatedaccount/uservice-utils/trunk-add-logging-decorator]

7. By Thomi Richards on 2015-04-02

Fix comments from code review.

=== modified file 'CHANGELOG'
--- CHANGELOG	2015-04-01 20:40:20 +0000
+++ CHANGELOG	2015-04-02 03:03:13 +0000
@@ -1,6 +1,12 @@
 Release History:
 ################
 
+NEXT
+====
+
+* Added `uservice_utils.logging.ExtraLogging` class to help manage passing
+ 'extra' arguments to multiple logging calls.
+
 1.0.0
 =====
 

=== modified file 'setup.py'
--- setup.py	2015-04-01 22:03:21 +0000
+++ setup.py	2015-04-02 03:03:13 +0000
@@ -49,6 +49,7 @@
     packages=find_packages(),
     test_suite='uservice_utils.tests',
     tests_require=[
+        'fixtures',
         'testtools',
     ],
     classifiers=[

=== modified file 'uservice_utils/logging.py'
--- uservice_utils/logging.py	2015-04-01 01:30:30 +0000
+++ uservice_utils/logging.py	2015-04-02 03:03:13 +0000
@@ -17,6 +17,7 @@
 
 """Code to configure logging for micro-services."""
 
+import collections
 import logging
 import logging.handlers
 import os
@@ -78,3 +79,62 @@
                 int(config['logstash']['version'])
             )
         )
+
+
+class ExtraLogger(logging.Logger):
+
+    """A logger that handles passing 'extra' arguments to all logging calls.
+
+    Tired of having to write:
+
+    logger.info("Some message", extra=extra)
+
+    ... everywhere?
+
+    Now you can install this class as the Logger class:
+
+    >>> import logging
+    >>> logging.setLoggerClass(ExtraLogger)
+
+    Then, to use it, get your logger as usual:
+
+    >>> logger = logging.getLogger(__name__)
+
+    ...and set your extra arguments once only:
+
+    >>> logger.set_extra_args(dict(foo='bar', baz='123'))
+
+    And those arguments will be included in all normal log messages:
+
+    >>> logger.info("Hello World") # message will contain extra args set above
+
+    Extra arguments can be passed to individual logging calls, and will take
+    priority over any set with the set_extra_args call.
+
+    """
+
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        self._extra_args = dict()
+
+    def set_extra_args(self, extra_args):
+        """Set the 'extra' arguments you want to be passed to every log message.
+
+        :param extra_args: A mapping type that contains the extra arguments you
+            want to store.
+        :raises TypeError: if extra_args is not a mapping type.
+
+        """
+        if not isinstance(extra_args, collections.Mapping):
+            raise TypeError("extra_args must be a mapping")
+        self._extra_args = extra_args
+
+    def makeRecord(self, name, level, fn, lno, msg, args, exc_info,
+                   func=None, user_extra=None, sinfo=None):
+        extra = self._extra_args.copy()
+        if user_extra:
+            extra.update(user_extra)
+        return super().makeRecord(name, level, fn, lno, msg, args, exc_info,
+                                  func, extra, sinfo)
+
+

=== modified file 'uservice_utils/tests/test_logging.py'
--- uservice_utils/tests/test_logging.py	2015-04-01 20:21:23 +0000
+++ uservice_utils/tests/test_logging.py	2015-04-02 03:03:13 +0000
@@ -17,21 +17,26 @@
 
 """Tests for the logging code."""
 
+import logging
 import os.path
 import subprocess
 import sys
 import tempfile
 from textwrap import dedent
 
+from fixtures import Fixture
 from testtools import TestCase
 from testtools.matchers import (
     Contains,
     Equals,
     FileContains,
+    IsInstance,
     Not,
 )
 
 import uservice_utils
+import uservice_utils.logging as util_logging
+
 
 class LoggingConfigurationTests(TestCase):
 
@@ -119,3 +124,66 @@
             self.expectThat(err, Not(Contains("Will not see")))
             self.expectThat(err, Contains("Will see"))
 
+
+class LoggerClassFixture(Fixture):
+
+    """A fixture that sets a new logging class for the duration of a test."""
+
+    def __init__(self, new_class):
+        self._new_class = new_class
+
+    def setUp(self):
+        super().setUp()
+        old_logger_class = logging.getLoggerClass()
+        logging.setLoggerClass(self._new_class)
+        self.addCleanup(logging.setLoggerClass, old_logger_class)
+
+
+class TestingLogFilter(logging.Filter):
+
+    """A filter that passes everything, but logs everything."""
+    def __init__(self):
+        self.log_records = []
+
+    def filter(self, record):
+        self.log_records.append(record)
+        return 1  # Log this record.
+
+
+class ExtraLoggerTests(TestCase):
+
+    def test_can_set_logger_class(self):
+        self.useFixture(LoggerClassFixture(util_logging.ExtraLogger))
+        logger = logging.getLogger(__name__)
+        self.assertThat(logger, IsInstance(util_logging.ExtraLogger))
+
+    def create_log_with_filter(self):
+        self.useFixture(LoggerClassFixture(util_logging.ExtraLogger))
+        logger = logging.getLogger(__name__)
+        logger.setLevel(logging.INFO)
+        filt = TestingLogFilter()
+        logger.addFilter(filt)
+        self.addCleanup(logger.removeFilter, filt)
+        return logger, filt
+
+    def test_can_set_extra_details(self):
+        logger, filt = self.create_log_with_filter()
+        logger.set_extra_args(dict(foo='bar'))
+        logger.info("Testing")
+
+        self.assertThat(filt.log_records[0].foo, Equals('bar'))
+
+    def test_extra_args_can_be_mixed(self):
+        logger, filt = self.create_log_with_filter()
+        logger.set_extra_args(dict(foo='bar'))
+        logger.info("Testing", extra=dict(bar='baz'))
+
+        self.assertThat(filt.log_records[0].foo, Equals('bar'))
+        self.assertThat(filt.log_records[0].bar, Equals('baz'))
+
+    def test_log_method_extra_args_take_priority(self):
+        logger, filt = self.create_log_with_filter()
+        logger.set_extra_args(dict(foo='bar'))
+        logger.info("Testing", extra=dict(foo='baz'))
+
+        self.assertThat(filt.log_records[0].foo, Equals('baz'))