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 frame.f_back and [
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 <module>
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 <module>
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 [
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')
):
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.