Merge pull request #1 from sprockets/implement-context-filter

Implement context filter

.travis.yml

@@ -6,9 +6,8 @@ python:
   - pypy
   - 3.4
 before_install:
-  - pip install codecov
+  - pip install nose coverage codecov
 install:
-  - pip install -r test-requirements.txt
   - pip install -e .
 script: nosetests
 after_success:

MANIFEST.in

@@ -1,7 +1,6 @@
 include LICENSE
 include README.rst
 include HISTORY.rst
-include *requirements.txt
 include tests.py
 graft docs
 global-exclude __pycache__

README.rst

@@ -2,7 +2,7 @@ sprockets.logging
 =================
 Making logs nicer since 2015!
 
-|Version| |Downloads| |Status| |Coverage| |License|
+|Version| |Downloads| |Travis| |CodeCov| |ReadTheDocs|
 
 Installation
 ------------
@@ -24,7 +24,7 @@ Requirements
 
 Example
 -------
-This examples demonstrates how to use ``sprockets.logging`` by ...
+This examples demonstrates the most basic usage of ``sprockets.logging``
 
 .. code-block:: python
 
@@ -33,21 +33,23 @@ This examples demonstrates how to use ``sprockets.logging`` by ...
 
    import sprockets.logging
 
+
    formatter = logging.Formatter('%(levelname)s %(message)s {%(context)s}')
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(formatter)
    handler.addFilter(sprockets.logging.ContextFilter(properties=['context']))
    logging.Logger.root.addHandler(handler)
+   logging.Logger.root.setLevel(logging.DEBUG)
 
-   # Outputs: INFO Hi there {}
+   # Outputs: INFO Hi there {None}
    logging.info('Hi there')
 
    # Outputs: INFO No KeyError {bah}
    logging.info('No KeyError', extra={'context': 'bah'})
 
    # Outputs: INFO Now with context! {foo}
    adapted = logging.LoggerAdapter(logging.Logger.root, extra={'context': 'foo'})
-   adapter.info('Now with context!')
+   adapted.info('Now with context!')
 
 Source
 ------
@@ -61,14 +63,14 @@ License
 .. |Version| image:: https://badge.fury.io/py/sprockets.logging.svg?
    :target: http://badge.fury.io/py/sprockets.logging
 
-.. |Status| image:: https://travis-ci.org/sprockets/sprockets.logging.svg?branch=master
+.. |Travis| image:: https://travis-ci.org/sprockets/sprockets.logging.svg?branch=master
    :target: https://travis-ci.org/sprockets/sprockets.logging
 
-.. |Coverage| image:: http://codecov.io/github/sprockets/sprockets.logging/coverage.svg?branch=master
+.. |CodeCov| image:: http://codecov.io/github/sprockets/sprockets.logging/coverage.svg?branch=master
    :target: https://codecov.io/github/sprockets/sprockets.logging?branch=master
 
 .. |Downloads| image:: https://pypip.in/d/sprockets.logging/badge.svg?
    :target: https://pypi.python.org/pypi/sprockets.logging
 
-.. |License| image:: https://pypip.in/license/sprockets.logging/badge.svg?
+.. |ReadTheDocs| image:: https://readthedocs.org/projects/sprocketslogging/badge/
    :target: https://sprocketslogging.readthedocs.org

docs/examples.rst

@@ -3,29 +3,17 @@ Examples
 
 Simple Usage
 ------------
-The following snippet uses :class:`sprockets.logging.filters.ContextFilter`
+The following snippet uses :class:`sprockets.logging.ContextFilter`
 to insert context information into a message using a
 :class:`logging.LoggerAdapter` instance.
 
-.. code-block:: python
+.. literalinclude:: ../examples/simple.py
 
-   import logging
-   import sys
+Dictionary-based Configuration
+------------------------------
+This package begins to shine if you use the dictionary-based logging
+configuration offered by :func:`logging.config.dictConfig`.  You can insert
+the custom filter and format string into the logging infrastructure and
+insert context easily with :class:`logging.LoggerAdapter`.
 
-   import sprockets.logging
-
-   formatter = logging.Formatter('%(levelname)s %(message)s {%(context)s}')
-   handler = logging.StreamHandler(sys.stdout)
-   handler.setFormatter(formatter)
-   handler.addFilter(sprockets.logging.ContextFilter(properties=['context']))
-   logging.Logger.root.addHandler(handler)
-
-   # Outputs: INFO Hi there {}
-   logging.info('Hi there')
-
-   # Outputs: INFO No KeyError {bah}
-   logging.info('No KeyError', extra={'context': 'bah'})
-
-   # Outputs: INFO Now with context! {foo}
-   adapted = logging.LoggerAdapter(logging.Logger.root, extra={'context': 'foo'})
-   adapter.info('Now with context!')
+.. literalinclude:: ../examples/tornado-app.py

docs/history.rst

@@ -3,4 +3,4 @@ Version History
 
 Next Release
 ------------
- - implement greatness
+ - Added :class:`sprockets.logging.ContextFilter`

docs/requirements.txt

@@ -0,0 +1,2 @@
+sphinx-rtd-theme
+sphinxcontrib-httpdomain

examples/simple.py

@@ -0,0 +1,22 @@
+import logging
+import sys
+
+import sprockets.logging
+
+
+formatter = logging.Formatter('%(levelname)s %(message)s {%(context)s}')
+handler = logging.StreamHandler(sys.stdout)
+handler.setFormatter(formatter)
+handler.addFilter(sprockets.logging.ContextFilter(properties=['context']))
+logging.Logger.root.addHandler(handler)
+logging.Logger.root.setLevel(logging.DEBUG)
+
+# Outputs: INFO Hi there {None}
+logging.info('Hi there')
+
+# Outputs: INFO No KeyError {bah}
+logging.info('No KeyError', extra={'context': 'bah'})
+
+# Outputs: INFO Now with context! {foo}
+adapted = logging.LoggerAdapter(logging.Logger.root, extra={'context': 'foo'})
+adapted.info('Now with context!')

examples/tornado-app.py

@@ -0,0 +1,77 @@
+import logging.config
+import signal
+import uuid
+
+from tornado import ioloop, web
+import sprockets.logging
+
+
+LOG_CONFIG = {
+   'version': 1,
+   'handlers': {
+      'console': {
+         'class': 'logging.StreamHandler',
+         'stream': 'ext://sys.stdout',
+         'formatter': 'simple',
+         'filters': ['context'],
+      },
+   },
+   'formatters': {
+      'simple': {
+         'class': 'logging.Formatter',
+         'format': '%(levelname)s %(name)s: %(message)s [%(context)s]',
+      },
+   },
+   'filters': {
+      'context': {
+         '()': 'sprockets.logging.ContextFilter',
+         'properties': ['context'],
+      },
+   },
+   'loggers': {
+      'tornado': {
+         'level': 'DEBUG',
+      },
+   },
+   'root': {
+      'handlers': ['console'],
+      'level': 'DEBUG',
+   },
+   'incremental': False,
+}
+
+
+class RequestHandler(web.RequestHandler):
+
+   def __init__(self, *args, **kwargs):
+      self.parent_log = kwargs.pop('parent_log')
+      super(RequestHandler, self).__init__(*args, **kwargs)
+
+   def prepare(self):
+      uniq_id = self.request.headers.get('X-UniqID', uuid.uuid4().hex)
+      self.logger = logging.LoggerAdapter(
+         self.parent_log.getChild('RequestHandler'),
+         extra={'context': uniq_id})
+
+   def get(self, object_id):
+      self.logger.debug('fetchin %s', object_id)
+      self.set_status(200)
+      return self.finish()
+
+def sig_handler(signo, frame):
+   logging.info('caught signal %d, stopping IO loop', signo)
+   iol = ioloop.IOLoop.instance()
+   iol.add_callback_from_signal(iol.stop)
+
+if __name__ == '__main__':
+   logging.config.dictConfig(LOG_CONFIG)
+   logger = logging.getLogger('app')
+   app = web.Application([
+      web.url('/(?P<object_id>\w+)', RequestHandler,
+              kwargs={'parent_log': logger}),
+   ])
+   app.listen(8000)
+   signal.signal(signal.SIGINT, sig_handler)
+   signal.signal(signal.SIGTERM, sig_handler)
+   ioloop.IOLoop.instance().start()
+   logger.info('IO loop stopped, exiting')

setup.py

@@ -7,23 +7,9 @@
 import sprockets.logging
 
 
-def read_requirements_file(req_name):
-    requirements = []
-    try:
-        with codecs.open(req_name, encoding='utf-8') as req_file:
-            for req_line in req_file:
-                if '#' in req_line:
-                    req_line = req_line[0:req_line.find('#')].strip()
-                if req_line:
-                    requirements.append(req_line.strip())
-    except IOError:
-        pass
-    return requirements
-
-
-install_requires = read_requirements_file('requirements.txt')
-setup_requires = read_requirements_file('setup-requirements.txt')
-tests_require = read_requirements_file('test-requirements.txt')
+install_requires = []
+setup_requires = []
+tests_require = ['nose>=1.3,<2']
 
 if sys.version_info < (3, 0):
     tests_require.append('mock')

sprockets/logging.py

@@ -1,5 +1,39 @@
 """
 Make good log output easier.
+
+- :class:`ContextFilter` adds fixed properties to a log record
+
 """
+from __future__ import absolute_import
+
+import logging
+
+
 version_info = (0, 0, 0)
 __version__ = '.'.join(str(v) for v in version_info)
+
+
+class ContextFilter(logging.Filter):
+    """
+    Ensures that properties exist on a LogRecord.
+
+    :param list|None properties: optional list of properties that
+        will be added to LogRecord instances if they are missing
+
+    This filter implementation will ensure that a set of properties
+    exists on every log record which means that you can always refer
+    to custom properties in a format string.  Without this, referring
+    to a property that is not explicitly passed in will result in an
+    ugly ``KeyError`` exception.
+
+    """
+
+    def __init__(self, name='', properties=None):
+        logging.Filter.__init__(self, name)
+        self.properties = list(properties) if properties else []
+
+    def filter(self, record):
+        for property_name in self.properties:
+            if not hasattr(record, property_name):
+                setattr(record, property_name, None)
+        return True

tests.py

@@ -0,0 +1,44 @@
+import logging
+import uuid
+import unittest
+
+import sprockets.logging
+
+
+class Prototype(object):
+    pass
+
+
+class RecordingHandler(logging.FileHandler):
+    def __init__(self):
+        logging.FileHandler.__init__(self, filename='/dev/null')
+        self.log_lines = []
+
+    def format(self, record):
+        log_line = logging.FileHandler.format(self, record)
+        self.log_lines.append(log_line)
+        return log_line
+
+
+class ContextFilterTests(unittest.TestCase):
+
+    def setUp(self):
+        super(ContextFilterTests, self).setUp()
+        self.logger = logging.getLogger(uuid.uuid4().hex)
+        self.handler = RecordingHandler()
+        self.logger.addHandler(self.handler)
+
+    def test_that_filter_blocks_key_errors(self):
+        formatter = logging.Formatter('%(message)s [%(context)s]')
+        self.handler.setFormatter(formatter)
+        self.handler.addFilter(sprockets.logging.ContextFilter(
+            properties=['context']))
+        self.logger.info('hi there')
+
+    def test_that_filter_does_not_overwrite_extras(self):
+        formatter = logging.Formatter('%(message)s [%(context)s]')
+        self.handler.setFormatter(formatter)
+        self.handler.addFilter(sprockets.logging.ContextFilter(
+            properties=['context']))
+        self.logger.info('hi there', extra={'context': 'foo'})
+        self.assertEqual(self.handler.log_lines[-1], 'hi there [foo]')

tox.ini

@@ -1,9 +1,10 @@
 [tox]
 envlist = py27,py34
 indexserver =
-	default = https://pypi.python.org/simple
+    default = https://pypi.python.org/simple
 toxworkdir = build/tox
+skip_missing_interpreters = true
 
 [testenv]
 commands = nosetests []
-deps = -rtest-requirements.txt
+deps = nose