Fix logging annoyance

Author: ulope

ethereum/__init__.py

@@ -4,6 +4,8 @@
 import os.path
 import subprocess
 import re
+# Import slogging to patch logging as soon as possible
+import slogging  # noqa
 
 
 GIT_DESCRIBE_RE = re.compile('^(?P<version>v\d+\.\d+\.\d+)-(?P<git>\d+-g[a-fA-F0-9]+(?:-dirty)?)$')

ethereum/slogging.py

@@ -1,5 +1,6 @@
 import logging
 import json
+import textwrap
 from logging import StreamHandler, Formatter, FileHandler
 from ethereum.utils import bcolors, isnumeric
 
@@ -18,15 +19,54 @@
 log_listeners = []
 
 
-# add level trace into logging
-def _trace(self, msg, *args, **kwargs):
-    if self.isEnabledFor(TRACE):
-        self._log(TRACE, msg, args, **kwargs)
-logging.Logger.trace = _trace
+def _inject_into_logger(name, code, namespace=None):
+    # This is a hack to fool the logging module into reporting correct source files.
+    # It determines the actual source of a logging call by inspecting the stack frame's
+    # source file. So we use this `eval(compile())` construct to "inject" our additional
+    # methods into the logging module.
+    if namespace is None:
+        namespace = {}
+    eval(
+        compile(
+            code,
+            logging._srcfile,
+            'exec'
+        ),
+        namespace
+    )
+    setattr(logging.Logger, name, namespace[name])
+
+
+# Add `trace()` level to Logger
+_inject_into_logger(
+    'trace',
+    textwrap.dedent(
+        """\
+        def trace(self, msg, *args, **kwargs):
+            if self.isEnabledFor(TRACE):
+                self._log(TRACE, msg, args, **kwargs)
+        """
+    ),
+    {'TRACE': TRACE}
+)
 logging.TRACE = TRACE
 logging.addLevelName(TRACE, "TRACE")
 
 
+# Add `DEV()` shortcut to loggers
+_inject_into_logger(
+    'DEV',
+    textwrap.dedent(
+        """\
+        def DEV(self, msg, *args, **kwargs):
+            '''Shortcut to output highlighted log text'''
+            kwargs['highlight'] = True
+            self.critical(msg, *args, **kwargs)
+        """
+    )
+)
+
+
 class LogRecorder(object):
 
     """
@@ -166,11 +206,6 @@ def _log(self, level, msg, args, **kwargs):
         msg = self.format_message(msg, kwargs, highlight, level)
         super(SLogger, self)._log(level, msg, args, exc_info, extra)
 
-    def DEV(self, msg, *args, **kwargs):
-        """Shortcut to output highlighted log text"""
-        kwargs['highlight'] = True
-        self.critical(msg, *args, **kwargs)
-
 
 class RootLogger(SLogger):
 

ethereum/tests/test_logging.py

@@ -49,7 +49,7 @@ def test_jsonconfig(caplog):
     slogging.configure(log_json=True)
     log = slogging.get_logger('prefix')
     log.warn('abc', a=1)
-    assert json.loads(caplog.records()[0].msg) == dict(event='prefix.abc', a=1, level='WARNING')
+    assert json.loads(caplog.records[0].msg) == dict(event='prefix.abc', a=1, level='WARNING')
 
 
 def test_configuration():
@@ -271,14 +271,14 @@ def test_bound_logger_isolation(caplog):
     bound_log_1 = real_log.bind(key1="value1")
     with caplog.at_level(slogging.TRACE):
         bound_log_1.info("test1")
-        records = caplog.records()
+        records = caplog.records
         assert len(records) == 1
         assert "test1" in records[0].msg
         assert 'key1=value1' in records[0].msg
 
     with caplog.at_level(slogging.TRACE):
         real_log.info("test2")
-        records = caplog.records()
+        records = caplog.records
         assert len(records) == 2
         assert "test2" in records[1].msg
         assert 'key1=value1' not in records[1].msg
@@ -289,7 +289,7 @@ def test_highlight(caplog):
     log = slogging.getLogger()
 
     log.DEV('testmessage')
-    assert "\033[91mtestmessage \033[0m" in caplog.records()[0].msg
+    assert "\033[91mtestmessage \033[0m" in caplog.records[0].msg
 
 
 def test_shortcut_dev_logger(capsys):
@@ -336,3 +336,19 @@ def test_logging_reconfigure_levels(config, logger, level):
 def test_set_level():
     slogging.set_level('test', 'CRITICAL')
     assert slogging.getLogger('test').level == logging.CRITICAL
+
+
+@pytest.mark.parametrize(
+    ('log_method', ), (
+        ('DEV', ),
+        ('trace', ),
+        ('info', ),
+    ))
+def test_logging_source_file(caplog, log_method):
+    slogging.configure(":trace")
+    logger = slogging.getLogger("test")
+    getattr(logger, log_method)("testmessage")
+
+    v = caplog.records[0]
+    print(v.pathname, v.module, v.name)
+    assert caplog.records[0].module == "test_logging"