I'm logging messages in django using raven and getsentry, but the logging seems to delay the execution of the code. For example:
# ...view code
tic = datetime.datetime.now()
logging.warning('foo warning')
toc = datetime.datetime.now()
print "log time %s, %s, %s" % (tic, toc, (toc - tic).total_seconds())
# more view code...
gives output:
log time 2013-09-25 12:03:56.541091, 2013-09-25 12:03:57.139420, 0.598329
ie it's delaying the execution of the code by 600ms in this case. Is this something to be expected? I would have thought the message would have been sent async in a separate thread so the main code doesn't get delayed. Also my ping time to app.getsentry.com is 125ms, so 600ms still seems strangely large even if the message is sent sync. Is there some config I can change to make things quicker?
settings file:
LOGGING = {
'version': 1,
'disable_existing_loggers': True,
'handlers': {
'sentry': {
'level': 'INFO',
'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler',
},
},
'loggers': {
'': {
'handlers': ['sentry'],
'level': 'INFO',
'propagate': True,
},
}
}
=== EDIT ===
Thanks to Filip Dupanović for pointing out the threading+ protocols. Sadly, they didn't work for me in gunicorn due to the threads being copied while booting workers. I fixed it by adding a post_fork hook in the gunicorn config file as follows:
import logging
from raven.contrib.django.handlers import SentryHandler
from raven.transport.threaded import ThreadedHTTPTransport
def post_fork(server, worker):
LOG = logging.getLogger()
for handler in LOG.handlers:
if isinstance(handler, SentryHandler):
for url, transport in handler.client._registry._transports.items():
if isinstance(transport, ThreadedHTTPTransport):
if hasattr(transport, '_worker'):
server.log.info("deleting sentry thread worker attribute")
delattr(transport, '_worker')
else:
server.log.info("sentry thread worker not present, nothing to do.")
Obv this is a hack and while it works for me I have no idea if it will work anywhere else.