Merge 559ae59 into 27cb2ab

AUTHORS.rst

@@ -23,6 +23,8 @@ The following folks helped forming structlog into what it is now:
 - `Tarek Ziadé <https://github.com/tarekziade>`_
 - `Thomas Heinrichsdobler <https://github.com/dertyp>`_
 - `Tom Lazar <https://github.com/tomster>`_
+- `George-Cristian Bîrzan <https://github.com/gcbirzan>`_
+
 
 Some of them disapprove of the addition of thread local context data. :)
 

docs/configuration.rst

@@ -100,6 +100,9 @@ So all it takes to use structlog with standard library logging is this::
    >>> log.critical('this is too easy!')
    event='this is too easy!'
 
+This uses a custom logger in order to override the default findCaller() so that it displays the correct caller.
+
+
 The :ref:`Twisted example <twisted-example>` shows how easy it is for Twisted.
 
 .. note::

structlog/stdlib.py

@@ -21,11 +21,53 @@
 from __future__ import absolute_import, division, print_function
 
 import logging
+import traceback
 import sys
 
 from structlog._base import BoundLoggerBase
 from structlog._exc import DropEvent
+from structlog._compat import PY3, StringIO
 
+class FixedFindCallerLoggerPy3(logging.Logger):
+    def findCaller(self, stack_info=False):
+        """
+        Finds the first caller frame outside of structlog so that the caller info is populated for wrapping stdlib.
+        This logger gets set as the default one when using LoggerFactory.
+        """
+        f = sys._getframe()
+        name = f.f_globals['__name__']
+        while name.startswith('structlog.') or name == 'logging':
+            f = f.f_back
+            name = f.f_globals['__name__']
+        sinfo = None
+        if stack_info:
+            sio = StringIO()
+            sio.write('Stack (most recent call last):\n')
+            traceback.print_stack(f, file=sio)
+            sinfo = sio.getvalue()
+            if sinfo[-1] == '\n':
+                sinfo = sinfo[:-1]
+            sio.close()
+
+        return f.f_code.co_filename, f.f_lineno, f.f_code.co_name, sinfo
+
+class FixedFindCallerLoggerPy2(logging.Logger):
+    def findCaller(self):
+        """
+        Finds the first caller frame outside of structlog so that the caller info is populated for wrapping stdlib.
+        This logger gets set as the default one when using LoggerFactory.
+        """
+        f = sys._getframe()
+        name = f.f_globals['__name__']
+        while name.startswith('structlog.') or name == 'logging':
+            f = f.f_back
+            name = f.f_globals['__name__']
+        return f.f_code.co_filename, f.f_lineno, f.f_code.co_name
+
+if PY3:
+    FixedFindCallerLogger= FixedFindCallerLoggerPy3
+else:
+    FixedFindCallerLogger= FixedFindCallerLoggerPy2
 
 class BoundLogger(BoundLoggerBase):
     """
@@ -80,7 +122,16 @@ class LoggerFactory(object):
     >>> from structlog import configure
     >>> from structlog.stdlib import LoggerFactory
     >>> configure(logger_factory=LoggerFactory())
+
+    :param bool fix_find_caller: By default False, it will fix the findCaller() of stdlib for wrapped loggers.
+
     """
+    def __init__(self, fix_find_caller=True, *args, **kwargs):
+        super(LoggerFactory, self).__init__(*args, **kwargs)
+        if fix_find_caller:
+            logging.setLoggerClass(FixedFindCallerLogger)
+
+
     def __call__(self):
         """
         Deduces the caller's module name and create a stdlib logger.

tests/test_stdlib.py

@@ -14,9 +14,12 @@
 
 from __future__ import absolute_import, division, print_function
 
+import os
+
 import logging
 
 import pytest
+from pretend import call_recorder
 
 from structlog._exc import DropEvent
 from structlog._loggers import ReturnLogger
@@ -26,7 +29,9 @@
     LoggerFactory,
     WARN,
     filter_by_level,
+    FixedFindCallerLogger,
 )
+from structlog._compat import PY3
 
 from .additional_frame import additional_frame
 
@@ -54,6 +59,43 @@ def test_deduces_correct_name(self):
         assert 'tests.test_stdlib' == LoggerFactory()().name
 
 
+    def test_deduces_correct_caller(self):
+        logger = FixedFindCallerLogger('test')
+        file_name, line_number, func_name = logger.findCaller()[:3]
+        assert file_name == os.path.realpath(__file__)
+        assert func_name == 'test_deduces_correct_caller'
+
+    @pytest.mark.skipif("sys.version_info <= (3,0)")
+    def test_stack_info_in_py3(self):
+        logger = FixedFindCallerLogger('test')
+        testing, is_, fun, stack_info = logger.findCaller(True)
+        assert 'testing, is_, fun' in stack_info
+
+    def test_find_caller(self, monkeypatch):
+        logger = LoggerFactory()()
+        log_handle = call_recorder(lambda x: None)
+        monkeypatch.setattr(logger, 'handle', log_handle)
+        logger.error('Test')
+        assert log_handle.calls
+        log_record = log_handle.calls[0].args[0]
+        assert log_record.funcName == 'test_find_caller'
+        assert log_record.name == __name__
+        assert log_record.filename == os.path.basename(__file__)
+
+
+    def test_sets_correct_logger(self):
+        original_class = logging.getLoggerClass()
+        try:
+            logging.setLoggerClass(logging.Logger)
+            LoggerFactory()
+            assert logging.getLoggerClass() is FixedFindCallerLogger
+            logging.setLoggerClass(logging.Logger)
+            LoggerFactory(fix_find_caller=False)
+            assert logging.getLoggerClass() is logging.Logger
+        finally:
+            logging.setLoggerClass(original_class)
+
+
 class TestFilterByLevel(object):
     def test_filters_lower_levels(self):
         logger = logging.Logger(__name__)