ansible/roles/fedmsg/base/templates/logging.py.j2

# Setup fedmsg logging.

# All of these modules are just used by the ContextInjector below.
import inspect
import hashlib
import logging
import os
import socket
import traceback

psutil = None
try:
    import psutil
except (OSError, ImportError):
    # We run into issues when trying to import psutil from inside mod_wsgi on
    # rhel7.  If we hit that here, then just fail quietly.
    # https://github.com/jmflinuxtx/kerneltest-harness/pull/17#issuecomment-48007837
    pass


radio_silence = """
*** %i instances of this error seen.  No more mail will be sent. ***
""".strip()

seen_errors = {}  # This could be a default dict.
error_limit = 100


class ContextInjector(logging.Filter):
    """ Logging filter that adds context to log records.

    Filters are typically used to "filter" log records.  They declare a filter
    method that can return True or False.  Only records with 'True' will
    actually be logged.

    Here, we somewhat abuse the concept of a filter.  We for the most part
    return true, but we use the opportunity to hang important contextual
    information on the log record to later be used by the logging Formatter.  We
    don't normally want to see all this stuff in normal log records, but we *do*
    want to see it when we are emailed error messages.  Seeing an error, but not
    knowing which host it comes from, is not that useful.

    After we've seen an error ~100 times, we stop sending email to avoid choking
    the world.

    http://docs.python.org/2/howto/logging-cookbook.html#filters-contextual
    """

    def filter(self, record):
        current_process = ContextInjector.get_current_process()
        current_hostname = socket.gethostname()

        record.host = current_hostname
        record.proc = current_process
        record.pid = current_process.pid
        record.proc_name = current_process.name
        record.command_line = current_process.cmdline
        # These are callabls on more modern versions of psutil.
        if callable(record.proc_name):
            record.proc_name = record.proc_name()
        if callable(record.command_line):
            record.command_line = record.command_line()
        record.command_line = " ".join(record.command_line)
        record.callstack = self.format_callstack()
        record.farewell = ""

        key = hashlib.sha256(record.callstack).hexdigest()
        if not key in seen_errors:
            seen_errors[key] = 0

        if seen_errors[key] > error_limit:
            return False

        seen_errors[key] += 1

        if seen_errors[key] > error_limit:
            record.farewell = radio_silence % error_limit

        return True

    @staticmethod
    def format_callstack():
        for i, frame in enumerate(f[0] for f in inspect.stack()):
            if not '__name__' in frame.f_globals:
                continue
            modname = frame.f_globals['__name__'].split('.')[0]
            if modname != "logging":
                break

        def _format_frame(frame):
            return '  File "%s", line %i in %s\n    %s' % (frame)

        stack = traceback.extract_stack()
        stack = stack[:-i]
        return "\n".join([_format_frame(frame) for frame in stack])

    @staticmethod
    def get_current_process():
        mypid = os.getpid()

        if not psutil:
            raise OSError("Could not import psutil for %r" % mypid)

        for proc in psutil.process_iter():
            if proc.pid == mypid:
                return proc

        # This should be impossible.
        raise ValueError("Could not find process %r" % mypid)

    @classmethod
    def __json__(cls):
        """ We need to be jsonifiable for "fedmsg-config" """
        return {'name': 'ContextInjector'}


hefty_format = """Message
-------
[%(asctime)s][%(name)10s %(levelname)7s]
%(message)s
%(farewell)s

Process Details
---------------
host:     %(host)s
PID:      %(pid)s
name:     %(proc_name)s
command:  %(command_line)s

Callstack that lead to the logging statement
--------------------------------------------
%(callstack)s
"""


# See the following for constraints on this format http://bit.ly/Xn1WDn
config = dict(
    logging=dict(
        version=1,
        formatters=dict(
            bare={
                "datefmt": "%Y-%m-%d %H:%M:%S",
                {% if inventory_hostname.startswith('bodhi-backend01') %}
                # Here we use a different format just so we can include
                # threadName.  We set the threadName in the bodhi masher to some
                # useful strings that will tell us which branch is doing what.
                # See https://github.com/fedora-infra/bodhi/commit/66d94094
                "format": "[%(asctime)s][%(name)10s %(levelname)7s]%(threadName)s %(message)s"
                {% else %}
                "format": "[%(asctime)s][%(name)10s %(levelname)7s] %(message)s"
                {% endif %}
            },
            hefty={
                "datefmt": "%Y-%m-%d %H:%M:%S",
                "format": hefty_format,
            },
        ),
        filters=dict(
            context={
                # This "()" syntax in the stdlib doesn't seem to be documented
                # anywhere.  I had to read
                # /usr/lib64/python2.7/logging/config.py to figure it out.
                "()": ContextInjector,
            },
        ),
        handlers=dict(
            console={
                "class": "logging.StreamHandler",
                "formatter": "bare",
                "level": "{{fedmsg_loglevel}}",
                "stream": "ext://sys.stdout",
            },
            mailer={
                "class": "logging.handlers.SMTPHandler",
                "formatter": "hefty",
                "filters": ["context"],
                "level": "ERROR",
                "mailhost": "bastion.phx2.fedoraproject.org",
                "fromaddr": "fedmsg@fedoraproject.org",
                "toaddrs": ["sysadmin-datanommer-members@fedoraproject.org"],
                "subject": "fedmsg error log %s" % socket.gethostname(),
            },
        ),
        loggers=dict(
            fedmsg={
                "level": "{{fedmsg_loglevel}}",
                "propagate": False,
                "handlers": ["console", "mailer"],
            },
            moksha={
                "level": "{{fedmsg_loglevel}}",
                "propagate": False,
                "handlers": ["console", "mailer"],
            },
        ),
    ),
)