From 1b875b543fa414c0971941b3bb2951e7523035aa Mon Sep 17 00:00:00 2001 From: Ralph Bean Date: Feb 27 2014 14:40:40 +0000 Subject: Add lots of context to fedmsg error emails. --- diff --git a/roles/fedmsg_base/templates/logging.py.j2 b/roles/fedmsg_base/templates/logging.py.j2 index 7153e9f..1f1ccb8 100644 --- a/roles/fedmsg_base/templates/logging.py.j2 +++ b/roles/fedmsg_base/templates/logging.py.j2 @@ -1,4 +1,88 @@ # Setup fedmsg logging. + +# All of these modules are just used by the ContextInjector below. +import inspect +import logging +import os +import psutil +import socket +import traceback + + +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 always 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. + + http://docs.python.org/2/howto/logging-cookbook.html#filters-contextual + """ + + def filter(self, record): + record.host = current_hostname + record.proc = current_process + record.pid = current_process.pid + record.proc_name = current_process.name + record.command_line = " ".join(current_process.cmdline) + record.callstack = self.format_callstack() + 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() + for proc in psutil.process_iter(): + if proc.pid == mypid: + return proc + + # This should be impossible. + raise ValueError("Could not find process %r" % mypid) + + +current_process = ContextInjector.get_current_process() +current_hostname = socket.gethostname() + +hefty_format = """Message +------- +[%(asctime)s][%(name)10s %(levelname)7s] +%(message)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( @@ -8,6 +92,18 @@ config = dict( "datefmt": "%Y-%m-%d %H:%M:%S", "format": "[%(asctime)s][%(name)10s %(levelname)7s] %(message)s" }, + 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={ @@ -18,8 +114,8 @@ config = dict( }, mailer={ "class": "logging.handlers.SMTPHandler", - # TODO -- potentially change this to a nicer mail formatter. - "formatter": "bare", + "formatter": "hefty", + "filters": ["context"], "level": "ERROR", "mailhost": "bastion.phx2.fedoraproject.org", "fromaddr": "fedmsg@fedoraproject.org",