Make a new logger with a fail method that is useful for errbacks.

Extracting useful tracebacks and line numbers from failures
withing twisted's deferred can be a pain. Hopefully this is a step
in the right direction.

lbrynet/core/log_support.py

@@ -1,4 +1,5 @@
 import datetime
+import inspect
 import json
 import logging
 import logging.handlers
@@ -14,6 +15,22 @@ import lbrynet
 from lbrynet.conf import settings
 from lbrynet.core import utils
 
+####
+# This code is copied from logging/__init__.py in the python source code
+####
+#
+# _srcfile is used when walking the stack to check when we've got the first
+# caller stack frame.
+#
+if hasattr(sys, 'frozen'): #support for py2exe
+    _srcfile = "logging%s__init__%s" % (os.sep, __file__[-4:])
+elif __file__[-4:].lower() in ['.pyc', '.pyo']:
+    _srcfile = __file__[:-4] + '.py'
+else:
+    _srcfile = __file__
+_srcfile = os.path.normcase(_srcfile)
+#####
+
 
 session = FuturesSession()
 
@@ -148,6 +165,30 @@ class JsonFormatter(logging.Formatter):
             data['exc_info'] = self.formatException(record.exc_info)
         return json.dumps(data)
 
+####
+# This code is copied from logging/__init__.py in the python source code
+####
+def findCaller(srcfile=None):
+    """Returns the filename, line number and function name of the caller"""
+    srcfile = srcfile or _srcfile
+    f = inspect.currentframe()
+    #On some versions of IronPython, currentframe() returns None if
+    #IronPython isn't run with -X:Frames.
+    if f is not None:
+        f = f.f_back
+    rv = "(unknown file)", 0, "(unknown function)"
+    while hasattr(f, "f_code"):
+        co = f.f_code
+        filename = os.path.normcase(co.co_filename)
+        # ignore any function calls that are in this file
+        if filename == srcfile:
+            f = f.f_back
+            continue
+        rv = (filename, f.f_lineno, co.co_name)
+        break
+    return rv
+###
+
 
 def failure(failure, log, msg, *args):
     """Log a failure message from a deferred.
@@ -287,3 +328,42 @@ class LogUploader(object):
         else:
             log_size = 0
         return cls(log_name, log_file, log_size)
+
+
+class Logger(logging.Logger):
+    """A logger that has an extra `fail` method useful for handling twisted failures."""
+    def fail(self):
+        """Returns a function to log a failure from an errback.
+
+        The returned function appends the error message and extracts
+        the traceback from `err`.
+
+        Example usage:
+            d.addErrback(log.fail(), 'This is an error message')
+
+        Although odd, making the method call is necessary to extract
+        out useful filename and line number information; otherwise the
+        reported values are from inside twisted's deferred handling
+        code.
+
+        Args (for the returned function):
+            err: twisted.python.failure.Failure
+            msg: the message to log, using normal logging string iterpolation.
+            args: the values to subtitute into `msg`
+            kwargs: set `level` to change from the default ERROR severity. Other
+                keywoards are treated as normal log kwargs.
+
+        """
+        fn, lno, func = findCaller()
+        def _fail(err, msg, *args, **kwargs):
+            level = kwargs.pop('level', logging.ERROR)
+            msg += ": %s"
+            args += (err.getErrorMessage(),)
+            exc_info = (err.type, err.value, err.getTracebackObject())
+            record = self.makeRecord(
+                self.name, level, fn, lno, msg, args, exc_info, func, kwargs)
+            self.handle(record)
+        return _fail
+
+
+logging.setLoggerClass(Logger)

tests/unit/core/test_log_support.py

@@ -0,0 +1,40 @@
+import StringIO
+import logging
+
+from twisted.internet import defer
+from twisted.trial import unittest
+
+from lbrynet.core import log_support
+
+
+class TestLogger(unittest.TestCase):
+    def raiseError(self):
+        raise Exception('terrible things happened')
+
+    def triggerErrback(self, log):
+        d = defer.Deferred()
+        d.addCallback(lambda _: self.raiseError())
+        d.addErrback(log.fail(), 'My message')
+        d.callback(None)
+        return d
+
+    def test_can_log_failure(self):
+        def output_lines():
+            return stream.getvalue().split('\n')
+
+        log = log_support.Logger('test')
+        stream = StringIO.StringIO()
+        handler = logging.StreamHandler(stream)
+        handler.setFormatter(logging.Formatter("%(filename)s:%(lineno)d - %(message)s"))
+        log.addHandler(handler)
+
+        # the line number could change if this file gets refactored
+        expected_first_line = 'test_log_support.py:17 - My message: terrible things happened'
+
+        # testing the entirety of the message is futile as the
+        # traceback will depend on the system the test is being run on
+        # but hopefully these two tests are good enough
+        d = self.triggerErrback(log)
+        d.addCallback(lambda _: self.assertEquals(expected_first_line, output_lines()[0]))
+        d.addCallback(lambda _: self.assertEqual(10, len(output_lines())))
+        return d