Logging/breadcrumb integration with multiple threads

[mikepurvis]

I'm trying to use raven.handlers.logging.SentryHandler to capture errors and exceptions in my application , but I'm getting some strange behaviour around breadcrumbs that I'm hoping I can get a little help understanding. Potentially this is related to #806 (which @mitsuhiko was looking at), but seeing this behaviour without multiprocessing involved felt like it warranted a new ticket.

MWE:

import raven
import logging
from raven.handlers.logging import SentryHandler
from time import sleep
from threading import Thread

logger = logging.getLogger('foo')
logger.setLevel(logging.DEBUG)
other_logger = logging.getLogger('bar')
other_logger.setLevel(logging.DEBUG)

client = raven.Client()
sentryLogHandler = SentryHandler(client, level="ERROR")
logger.addHandler(sentryLogHandler)
other_logger.addHandler(sentryLogHandler)

sh = logging.StreamHandler()
logger.addHandler(sh)
other_logger.addHandler(sh)

logger.debug("1")
logger.info("2")
other_logger.info("3")

def foo():
    other_logger.info("4")
    logger.critical("5")
t = Thread(target=foo)
t.start()
sleep(0.1)

logger.critical("6")

Output in the console (via StreamHandler) is as expected:

1
2
3
4
5
6

However, in Sentry:

• The event for 6 is missing the breadcrumbs for 4 and 5 (from the other thread), and
• The event for 5 has no breadcrumbs at all, not even the 4 one from within the same thread.

Any idea what's going on here?

[mikepurvis]

Oh, it seems that the breadcrumb capture doesn't happen via raven.handlers.logging.SentryHandler at all— it's this monkey-patch of the logging module itself:

raven-python/raven/breadcrumbs.py

Lines 157 to 186 in c69abaa

	# This requires a bit of explanation why we're doing this. Due to how
	# logging itself works we need to pretend that the method actually was
	# created within the logging module. There are a few ways to detect
	# this and we fake all of them: we use the same function globals (the
	# one from the logging module), we create it entirely there which
	# means that also the filename is set correctly. This fools the
	# detection code in logging and it makes logging itself skip past our
	# code when determining the code location.
	#
	# Because we point the globals to the logging module we now need to
	# refer to our own functions (original and the crumb recording
	# function) through a closure instead of the global scope.
	#
	# We also add a lot of newlines in front of the code so that the
	# code location lines up again in case someone runs inspect.getsource
	# on the function.
	ns = {}
	eval(compile('''%(offset)sif 1:
	def factory(original, record_crumb):
	def %(name)s(self, %(args)s, *args, **kwargs):
	record_crumb(self, %(fwd)s, *args, **kwargs)
	return original(self, %(args)s, *args, **kwargs)
	return %(name)s
	\n''' % {
	'offset': '\n' * (code.co_firstlineno - 3),
	'name': func.__name__,
	'args': ', '.join(args),
	'fwd': fwd,
	'level': level,
	}, logging._srcfile, 'exec'), logging.__dict__, ns)

---

However, it looks like this is an issue with breadcrumbs more than with the logging patch— even when I just do a straight up raven.breadcrumbs.record, it makes it in from the main thread, but not the other one.

---

Here it is— breadcrumbs are stored as part of the "context", which is thread-local:

raven-python/raven/context.py

Lines 22 to 51 in c69abaa

	_active_contexts = local()
	def get_active_contexts():
	"""Returns all the active contexts for the current thread."""
	try:
	return list(_active_contexts.contexts)
	except AttributeError:
	return []
	class Context(local, Mapping, Iterable):
	"""
	Stores context until cleared.
	>>> def view_handler(view_func, *args, **kwargs):
	>>> context = Context()
	>>> context.merge(tags={'key': 'value'})
	>>> try:
	>>> return view_func(*args, **kwargs)
	>>> finally:
	>>> context.clear()
	"""
	def __init__(self, client=None):
	breadcrumbs = raven.breadcrumbs.make_buffer(
	client is None or client.enable_breadcrumbs)
	if client is not None:
	client = weakref(client)
	self._client = client

---

So, this feels like a giant hack, but I get the behaviour I would like if I manually alias the thread's context's BreadcrumbBuffer back to the global instance, like so:

logger.debug("1")
logger.info("2")
other_logger.info("3")
record('aaa')
global_breadcrumbs = client.context.breadcrumbs

def foo():
    client.context.activate()
    client.context.breadcrumbs = global_breadcrumbs
    record('bbb')
    other_logger.info("4")
    logger.critical("5")
t = Thread(target=foo)
t.start()
sleep(0.1)

logger.critical("6")

This will allow me to move forward, but it would be great to have any thoughts on whether there are better ways to solve this.