Fix hynek#19 Pass positional arguments down to stdlib

docs/changelog.rst

@@ -1,6 +1,7 @@
 Changelog
 =========
 
+- :bug:`19` Pass positional arguments to stdlib wrapped loggers that use string formatting.
 - :bug:`-` Various doc fixes.
 - :release:`0.4.0 <2013-11-10>`
 - :feature:`6` Add :class:`structlog.processors.StackInfoRenderer` for adding stack information to log entries without involving exceptions.

structlog/_base.py

@@ -143,7 +143,8 @@ def _process_event(self, method_name, event, event_kw):
         else:
             return event_dict
 
-    def _proxy_to_logger(self, method_name, event=None, **event_kw):
+    def _proxy_to_logger(self, method_name, event=None, *event_args,
+                         **event_kw):
         """
         Run processor chain on event & call *method_name* on wrapped logger.
 
@@ -168,6 +169,7 @@ def _proxy_to_logger(self, method_name, event=None, **event_kw):
         """
         try:
             args, kw = self._process_event(method_name, event, event_kw)
+            args = args[:] + event_args
             return getattr(self._logger, method_name)(*args, **kw)
         except DropEvent:
             return

structlog/processors.py

@@ -307,3 +307,30 @@ def __call__(self, logger, name, event_dict):
                 _find_first_app_frame_and_name()[0]
             )
         return event_dict
+
+
+class StdlibFormatEventRenderer(object):
+    """
+    Applies stdlib-like string formatting to the `event` key with the arguments
+    in the `positional_args` key. This is populated by
+    `structlog.stdlib.BoundLogger` or can be manually set.
+
+    `positional_args` can be any iterable, but a dictionary as the single
+    element of the tuple is used instead of the tuple, to mantain compatibility
+    with the undocumented feature of stdlib logging.
+
+    """
+    def __init__(self, strip_positional_args=False):
+        self.strip_positional_args = strip_positional_args
+        super(StdlibFormatEventRenderer, self).__init__()
+
+    def __call__(self, _, __, event_dict):
+        args = event_dict.get('positional_args')
+        if args:
+            args = tuple(args)
+            if len(args) == 1 and isinstance(args[0], dict) and args[0]:
+                args = args[0]
+            event_dict['event'] = event_dict['event'] % args
+            if self.strip_positional_args:
+                event_dict.pop('positional_args')
+        return event_dict

structlog/stdlib.py

@@ -62,37 +62,48 @@ class BoundLogger(BoundLoggerBase):
         )
 
     """
-    def debug(self, event=None, **kw):
+    def __getattr__(self, item):
+        return getattr(self._logger, item)
+
+    def debug(self, event=None, *args, **kw):
         """
         Process event and call ``Logger.debug()`` with the result.
         """
-        return self._proxy_to_logger('debug', event, **kw)
+        return self._proxy_to_logger('debug', event, *args, **kw)
 
-    def info(self, event=None, **kw):
+    def info(self, event=None, *args, **kw):
         """
         Process event and call ``Logger.info()`` with the result.
         """
-        return self._proxy_to_logger('info', event, **kw)
+        return self._proxy_to_logger('info', event, *args, **kw)
 
-    def warning(self, event=None, **kw):
+    def warning(self, event=None, *args, **kw):
         """
         Process event and call ``Logger.warning()`` with the result.
         """
-        return self._proxy_to_logger('warning', event, **kw)
+        return self._proxy_to_logger('warning', event, *args, **kw)
 
     warn = warning
 
-    def error(self, event=None, **kw):
+    def error(self, event=None, *args, **kw):
         """
         Process event and call ``Logger.error()`` with the result.
         """
-        return self._proxy_to_logger('error', event, **kw)
+        return self._proxy_to_logger('error', event, *args, **kw)
 
-    def critical(self, event=None, **kw):
+    def critical(self, event=None, *args, **kw):
         """
         Process event and call ``Logger.critical()`` with the result.
         """
-        return self._proxy_to_logger('critical', event, **kw)
+        return self._proxy_to_logger('critical', event, *args, **kw)
+
+    def _proxy_to_logger(self, method_name, event=None, *event_args,
+                         **event_kw):
+        if event_args:
+            event_kw['positional_args'] = event_args
+        return super(BoundLogger, self)._proxy_to_logger(method_name, event,
+                                                         *event_args,
+                                                         **event_kw)
 
 
 class LoggerFactory(object):

tests/test_processors.py

@@ -34,7 +34,7 @@
     UnicodeEncoder,
     _JSONFallbackEncoder,
     format_exc_info,
-)
+    StdlibFormatEventRenderer)
 from structlog.threadlocal import wrap_dict
 
 
@@ -268,3 +268,25 @@ def test_adds_stack_if_asked(self, sir):
     def test_renders_correct_stack(self, sir):
         ed = sir(None, None, {'stack_info': True})
         assert "ed = sir(None, None, {'stack_info': True})" in ed['stack']
+
+
+class TestStringFormatting(object):
+    def test_formats_tuple(self):
+        renderer = StdlibFormatEventRenderer()
+        event_dict = renderer(None, None, {'event': '%d %d %s',
+                                           'positional_args': [1, 2, 'test']})
+        assert event_dict['event'] == '1 2 test'
+
+    def test_formats_dict(self):
+        renderer = StdlibFormatEventRenderer()
+        event_dict = renderer(None, None, {'event': '%(foo)s bar',
+                                           'positional_args': (
+                                               {'foo': 'bar'},)})
+        assert event_dict['event'] == 'bar bar'
+
+    def test_pops_positional_args(self):
+        renderer = StdlibFormatEventRenderer(strip_positional_args=True)
+        event_dict = renderer(None, None, {'event': '%d %d %s',
+                                           'positional_args': [1, 2, 'test']})
+        assert event_dict['event'] == '1 2 test'
+        assert 'positional_args' not in event_dict