lbry-sdk/lbrynet/core/log_support.py

import inspect
import json
import logging
import logging.handlers
import os
import sys
import traceback

from txrequests import Session
from requests.exceptions import ConnectionError
from twisted.internet import defer
import twisted.python.log

from lbrynet import __version__ as lbrynet_version, build_type, conf
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)
#####


TRACE = 5


class HTTPSHandler(logging.Handler):
    def __init__(self, url, fqdn=False, localname=None, facility=None, session=None):
        logging.Handler.__init__(self)
        self.url = url
        self.fqdn = fqdn
        self.localname = localname
        self.facility = facility
        self.session = session if session is not None else Session()

    def get_full_message(self, record):
        if record.exc_info:
            return '\n'.join(traceback.format_exception(*record.exc_info))
        else:
            return record.getMessage()

    @defer.inlineCallbacks
    def _emit(self, record):
        payload = self.format(record)
        try:
            yield self.session.post(self.url, data=payload)
        except ConnectionError:
            pass

    def emit(self, record):
        return self._emit(record)


DEFAULT_FORMAT = "%(asctime)s %(levelname)-8s %(name)s:%(lineno)d: %(message)s"
DEFAULT_FORMATTER = logging.Formatter(DEFAULT_FORMAT)
LOGGLY_URL = "https://logs-01.loggly.com/inputs/{token}/tag/{tag}"


def remove_handlers(log, handler_name):
    for handler in log.handlers:
        if handler.name == handler_name:
            log.removeHandler(handler)


def _log_decorator(fn):
    """Configure a logging handler.

    `fn` is a function that returns a logging handler. The returned
    handler has its log-level set and is attached to the specified
    logger or the root logger.
    """

    def helper(*args, **kwargs):
        log = kwargs.pop('log', logging.getLogger())
        level = kwargs.pop('level', logging.INFO)
        if not isinstance(level, int):
            # despite the name, getLevelName returns
            # the numeric level when passed a text level
            level = logging.getLevelName(level)
        handler = fn(*args, **kwargs)
        configure_handler(handler, log, level)
        return handler

    return helper


def configure_handler(handler, log, level):
    if handler.name:
        remove_handlers(log, handler.name)
    handler.setLevel(level)
    log.addHandler(handler)
    # need to reduce the logger's level down to the
    # handler's level or else the handler won't
    # get those messages
    if log.level > level:
        log.setLevel(level)
    return handler


def disable_third_party_loggers():
    logging.getLogger('requests').setLevel(logging.WARNING)
    logging.getLogger('urllib3').setLevel(logging.WARNING)
    logging.getLogger('BitcoinRPC').setLevel(logging.INFO)
    logging.getLogger('lbryum').setLevel(logging.WARNING)
    logging.getLogger('twisted').setLevel(logging.WARNING)


@_log_decorator
def configure_console(**kwargs):
    """Convenience function to configure a log-handler that outputs to stdout"""
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(DEFAULT_FORMATTER)
    handler.name = 'console'
    return handler


@_log_decorator
def configure_file_handler(file_name, **kwargs):
    """Convenience function to configure a log-handler that writes to `file_name`"""
    handler = logging.handlers.RotatingFileHandler(file_name, maxBytes=2097152, backupCount=5)
    handler.setFormatter(DEFAULT_FORMATTER)
    handler.name = 'file'
    return handler


def get_loggly_url(token=None, version=None):
    token = token or utils.deobfuscate(conf.settings['LOGGLY_TOKEN'])
    version = version or lbrynet_version
    return LOGGLY_URL.format(token=token, tag='lbrynet-' + version)


def configure_loggly_handler(*args, **kwargs):
    if build_type.BUILD == 'dev':
        return
    level = kwargs.pop('level', logging.WARNING)
    _configure_loggly_handler(*args, level=level, **kwargs)


@_log_decorator
def _configure_loggly_handler(url=None, **kwargs):
    url = url or get_loggly_url()
    formatter = JsonFormatter(**kwargs)
    handler = HTTPSHandler(url)
    handler.setFormatter(formatter)
    handler.name = 'loggly'
    return handler


class JsonFormatter(logging.Formatter):
    """Format log records using json serialization"""

    def __init__(self, **kwargs):
        self.attributes = kwargs

    def format(self, record):
        data = {
            'loggerName': record.name,
            'asciTime': self.formatTime(record),
            'fileName': record.filename,
            'functionName': record.funcName,
            'levelNo': record.levelno,
            'lineNo': record.lineno,
            'levelName': record.levelname,
            'message': record.getMessage(),
        }
        data.update(self.attributes)
        if record.exc_info:
            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.

    Args:
        failure: twisted.python.failure.Failure
        log: a python logger instance
        msg: the message to log. Can use normal logging string interpolation.
             the last argument will be set to the error message from the failure.
        args: values to substitute into `msg`
    """
    args += (failure.getErrorMessage(),)
    exc_info = (failure.type, failure.value, failure.getTracebackObject())
    log.error(msg, *args, exc_info=exc_info)


def convert_verbose(verbose):
    """Convert the results of the --verbose flag into a list of logger names

    if --verbose is not provided, args.verbose will be None and logging
    should be at the info level.
    if --verbose is provided, but not followed by any arguments, then
    args.verbose = [] and debug logging should be enabled for all of lbrynet
    along with info logging on lbryum.
    if --verbose is provided and followed by arguments, those arguments
    will be in a list
    """
    if verbose is None:
        return []
    if verbose == []:
        return ['lbrynet', 'lbryum']
    return verbose


def configure_logging(file_name, console, verbose=None):
    """Apply the default logging configuration.

    Enables two log-handlers at the INFO level: a file logger and a loggly logger.
    Optionally turns on a console logger that defaults to the INFO level, with
    specified loggers being set to the DEBUG level.

    Args:
        file_name: the file to which logs should be saved
        console: If true, enable a console logger
        verbose: a list of loggers to set to debug level.
            See `convert_verbose` for more details.
    """
    verbose = convert_verbose(verbose)
    configure_twisted()
    configure_file_handler(file_name)
    configure_loggly_handler()
    disable_third_party_loggers()
    if console:
        # if there are some loggers at the debug level, we need
        # to enable the console to allow debug. Otherwise, only
        # allow info.
        level = 'DEBUG' if verbose else 'INFO'
        handler = configure_console(level=level)
        if 'lbryum' in verbose:
            # TODO: this enables lbryum logging on the other handlers
            # too which isn't consistent with how verbose logging
            # happens with other loggers. Should change the configuration
            # so that its only logging at the INFO level for the console.
            logging.getLogger('lbryum').setLevel(logging.INFO)
            verbose.remove('lbryum')
        if verbose:
            handler.addFilter(LoggerNameFilter(verbose))


def configure_twisted():
    """Setup twisted logging to output events to the python stdlib logger"""
    # I tried using the new logging api
    # https://twistedmatrix.com/documents/current/core/howto/logger.html#compatibility-with-standard-library-logging
    # and it simply didn't work
    observer = twisted.python.log.PythonLoggingObserver()
    observer.start()


class LoggerNameFilter(object):
    """Filter a log record based on its name.

    Allows all info level and higher records to pass thru.
    Debug records pass if the log record name (or a parent) match
    the input list of logger names.
    """

    def __init__(self, logger_names):
        self.logger_names = logger_names

    def filter(self, record):
        if record.levelno >= logging.INFO:
            return True
        name = record.name
        while name:
            if name in self.logger_names:
                return True
            name = get_parent(name)
        return False


def get_parent(logger_name):
    names = logger_name.split('.')
    if len(names) == 1:
        return ''
    names = names[:-1]
    return '.'.join(names)


class Logger(logging.Logger):
    """A logger that has an extra `fail` method useful for handling twisted failures."""

    def fail(self, callback=None, *args, **kwargs):
        """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:
            callback: callable to call after making the log. The first argument
                will be the `err` from the deferred
            args: extra arguments to pass into `callback`

        Returns: a function that takes the following arguments:
            err: twisted.python.failure.Failure
            msg: the message to log, using normal logging string iterpolation.
            msg_args: the values to subtitute into `msg`
            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, *msg_args, **msg_kwargs):
            level = msg_kwargs.pop('level', logging.ERROR)
            msg += ": %s"
            msg_args += (err.getErrorMessage(),)
            exc_info = (err.type, err.value, err.getTracebackObject())
            record = self.makeRecord(
                self.name, level, fn, lno, msg, msg_args, exc_info, func, msg_kwargs)
            self.handle(record)
            if callback:
                try:
                    return callback(err, *args, **kwargs)
                except Exception:
                    # log.fail is almost always called within an
                    # errback. If callback fails and we didn't catch
                    # the exception we would need to attach a second
                    # errback to deal with that, which we will almost
                    # never do and then we end up with an unhandled
                    # error that will get swallowed by twisted
                    self.exception('Failed to run callback')

        return _fail

    def trace(self, msg, *args, **kwargs):
        if self.isEnabledFor(TRACE):
            self._log(TRACE, msg, args, **kwargs)


logging.setLoggerClass(Logger)
logging.addLevelName(TRACE, 'TRACE')