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
import twisted.python.log

from lbrynet import __version__ as lbrynet_version, analytics, 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


def bg_cb(sess, resp):
    """ Don't do anything with the response """
    pass


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()

    def emit(self, record):
        try:
            payload = self.format(record)
            self.session.post(self.url, data=payload, background_callback=bg_cb)
        except (KeyboardInterrupt, SystemExit):
            raise
        except:
            self.handleError(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 configure_analytics_handler(analytics_manager):
    handler = analytics.Handler(analytics_manager)
    handler.name = 'analytics'
    return configure_handler(handler, logging.getLogger(), logging.ERROR)


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')