ionel's codelog

Adding stacktraces to log messages

Tue 10 December 2013

I always had this issue with libraries that logs useful stuff but make figuring out how you called said library very hard. For example, Django logs SQL queries but it's hard to figure out what code made the ORM query. This is a huge pain for Ajax requests - django-debug-toolbar can't help you much with those ... well, not yet.

Turns out Python's logging module allows custom formatters. How about we write one ?

The filter is just a class with a filter(record) method. It appears that filter can be called multiple times so we need to make sure we don't patch the record more than 1 time:

class WithStacktrace(object):
    def filter(self, record):
        if not hasattr(record, 'stack_patched'):
            record.msg += " -- Stack: \n" + ''.join(format_stack(f=sys._getframe(1)))
            record.stack_patched = True
        return True

You probably notice now the stacktrace can get rather long, and it includes useless frames from the logging module. We can fix that by blacklisting frames from logging or whatever we chose to ignore (like the django.db package):

import sys
from traceback import format_stack

class WithStacktrace(object):
    def __init__(self, skip=[], limit=5):
        self.skip = [__name__, 'logging']
        self.skip.extend(skip)
        self.limit = limit

    def filter(self, record):
        if not hasattr(record, 'stack_patched'):
            frame = sys._getframe(1)
            if self.skip:
                while [skip for skip in self.skip if frame.f_globals.get('__name__', '').startswith(skip)]:
                    frame = frame.f_back

            record.msg += " -- Stack: \n" + ''.join(format_stack(f=frame, limit=self.limit)).rstrip()
            record.stack_patched = True
        return True

This will "skip" frames till it finds a frame that's not from a blacklisted module.

If we're using Django we can just add this in the settings (assuming we import or define WithStacktrace in the settings):

LOGGING['loggers']['django.db.backends'] = {
    'level': 'DEBUG',
    'filters': ['add_stack'],
}
LOGGING.setdefault('filters', {})['add_stack'] = {
    '()': WithStacktrace,
    'skip': ("django.db", "south.", "__main__"),
    'limit': 1, # just one frame, increase this if not enough
}

It would look like this:

[2013-12-07 17:58:17,297] DEBUG - django.db.backends - (0.001) SELECT "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "auth_user" WHERE "auth_user"."username" = 'ionelmc' ; args=('ionelmc',) -- Stack:
  File "foobar.py", line 2, in 
    list(User.objects.filter(username='ionelmc'))
[2013-12-07 17:58:18,819] DEBUG - django.db.backends - (1.522) select id, username, pg_sleep(0.01) from auth_user; args=() -- Stack:
  File "foobar.py", line 3, in 
    User.objects.raw('select id, username, pg_sleep(0.01) from auth_user')[0]

I believe this is very dull, and since we're most probably running the app in the terminal (you would only want all this detail in development) we could use some colors. Let's spice it up with a better filter:

import sys
try:
    from sqlparse import format as sqlformat
except ImportError:
    sqlformat = lambda s, reindent=None: s
from traceback import format_stack

class WithStacktrace(object):
    def __init__(self, skip=[], limit=5):
        self.skip = [__name__, 'logging']
        self.skip.extend(skip)
        self.limit = limit

    def filter(self, record):
        if not hasattr(record, 'stack_patched'):
            frame = sys._getframe(1)
            if self.skip:
                while [skip for skip in self.skip if frame.f_globals.get('__name__', '').startswith(skip)]:
                    frame = frame.f_back
            if hasattr(record, 'duration') and hasattr(record, 'sql') and hasattr(record, 'params'):
                record.msg = "\x1b[31mduration: %s%.4f secs\x1b[0m, \x1b[33marguments: %s%s\x1b[0m\n  \x1b[1;33m%s\x1b[0m\n -- stack: \n\x1b[32m%s\x1b[0m" % (
                    "\x1b[31m" if record.duration < 0.1 else "\x1b[1;31m", record.duration,
                    "\x1b[1;33m" if record.params else '', record.params,
                    '\n  '.join(sqlformat(record.sql, reindent=True).strip().splitlines()),
                    ''.join(format_stack(f=frame, limit=self.limit)).rstrip()
                )
            else:
                record.msg += "\n -- stack: \n\x1b[32m%s\x1b[0m" % (
                    ''.join(format_stack(f=frame, limit=self.limit)).rstrip()
                )
            record.stack_patched = True
        return True

Output would look like this:

[2013-12-07 18:12:48,382] DEBUG - django.db.backends - duration: 0.0009 secs, arguments: ('ionelmc',)
  SELECT "auth_user"."id",
         "auth_user"."password",
         "auth_user"."last_login",
         "auth_user"."is_superuser",
         "auth_user"."username",
         "auth_user"."first_name",
         "auth_user"."last_name",
         "auth_user"."email",
         "auth_user"."is_staff",
         "auth_user"."is_active",
         "auth_user"."date_joined"
  FROM "auth_user"
  WHERE "auth_user"."username" = 'ionelmc'
 -- stack:
  File "foobar.py", line 2, in <module>
    list(User.objects.filter(username='ionelmc'))
[2013-12-07 18:12:49,911] DEBUG - django.db.backends - duration: 1.5223 secs, arguments: ()
  select id,
         username,
         pg_sleep(0.01)
  from auth_user
 -- stack:
  File "foobar.py", line 3, in <module>
    User.objects.raw('select id, username, pg_sleep(0.01) from auth_user')[0]

We can take it even further by coloring the SQL and tracebacks using pygments. It would look like this:

import sys
import sqlparse
from traceback import format_stack
from pygments import highlight
from pygments.lexers import SqlLexer, PythonTracebackLexer
from pygments.formatters import Terminal256Formatter, TerminalFormatter

class WithStacktrace(object):
    _term_formatter = TerminalFormatter(bg='dark')
    _sql_lexer = SqlLexer()
    _tb_lexer = PythonTracebackLexer()

    def __init__(self, skip=(), limit=5):
        self.skip = [__name__, 'logging']
        self.skip.extend(skip)
        self.limit = limit

    def filter(self, record):
        if not hasattr(record, 'stack_patched'):
            frame = sys._getframe(1)
            if self.skip:
                while frame and [m for m in self.skip if frame.f_globals.get('__name__', '').startswith(m)]:
                    frame = frame.f_back
            if hasattr(record, 'duration') and hasattr(record, 'sql') and hasattr(record, 'params'):
                if record.duration < 0.1:
                    record.msg = "\x1b[31mduration: %.4f secs\x1b[0m" % record.duration
                else:
                    record.msg = "\x1b[31mduration: \x1b[1;31m%.4f secs\x1b[0m" % record.duration
                if record.params:
                    record.msg += ", \x1b[33marguments: \x1b[1;33m%s\x1b[0m" % (record.params, )
                else:
                    record.msg += ", \x1b[33marguments: %s\x1b[0m" % (record.params, )
                sql = record.sql
                try:
                    sql = '\n  '.join(sqlparse.format(sql, reindent=True).strip().splitlines())
                    sql = highlight(sql, self._sql_lexer, self._term_formatter)
                except Exception as ex:
                    pass
                record.msg += "\n  \x1b[1;33m%s\x1b[0m" % sql
                if frame:
                    tb = ''.join(format_stack(f=frame, limit=self.limit))
                    try:
                        record.msg += " -- stack: \n%s" % highlight(tb, self._tb_lexer, self._term_formatter).rstrip()
                    except Exception as ex:
                        record.msg += " -- stack: \n\x1b[32m%s\x1b[0m" % tb.rstrip()

            record.stack_patched = True
        return True

The output would look like this:

[2013-12-07 18:10:56,766] DEBUG - django.db.backends - duration: 0.0009 secs, arguments: ('ionelmc',)
  SELECT "auth_user"."id",
         "auth_user"."password",
         "auth_user"."last_login",
         "auth_user"."is_superuser",
         "auth_user"."username",
         "auth_user"."first_name",
         "auth_user"."last_name",
         "auth_user"."email",
         "auth_user"."is_staff",
         "auth_user"."is_active",
         "auth_user"."date_joined"
  FROM "auth_user"
  WHERE "auth_user"."username" = 'ionelmc'
 -- stack:
  File "foobar.py", line 2, in <module>
    list(User.objects.filter(username='ionelmc'))
[2013-12-07 18:10:58,304] DEBUG - django.db.backends - duration: 1.5201 secs, arguments: ()
  select id,
         username,
         pg_sleep(0.01)
  from auth_user
 -- stack:
  File "foobar.py", line 3, in <module>
    User.objects.raw('select id, username, pg_sleep(0.01) from auth_user')[0]

I think it doesn't look much better ...

Notes:

  • The output snippets are created with ansi2html.
  • An astute reader will point out that there's django.utils.termcolors or some other handy library ... but I don't think it's really needed.

This entry was tagged as python django debugging

blog comments powered by Disqus