diff --git a/lbrynet/core/log_support.py b/lbrynet/core/log_support.py index 39ffe867e..9f6ad2222 100644 --- a/lbrynet/core/log_support.py +++ b/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) diff --git a/tests/unit/core/test_log_support.py b/tests/unit/core/test_log_support.py new file mode 100644 index 000000000..07ea5946d --- /dev/null +++ b/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