Merge branch 'feature/breadcrumbs'

7 files changed, 531 insertions, 28 deletions

diff --git a/raven/_compat.py b/raven/_compat.py
index bd5c5e7..3d5e28d 100644
--- a/raven/_compat.py
+++ b/raven/_compat.py
@@ -175,3 +175,10 @@ else:
 def with_metaclass(meta, base=object):
     """Create a base class with a metaclass."""
     return meta("NewBase", (base,), {})
+
+
+def get_code(func):
+    rv = getattr(func, '__code__', getattr(func, 'func_code', None))
+    if rv is None:
+        raise TypeError('Could not get code from %r' % type(func).__name__)
+    return rv
diff --git a/raven/base.py b/raven/base.py
index dbe8038..59388b2 100644
--- a/raven/base.py
+++ b/raven/base.py
@@ -28,7 +28,6 @@ else:
 import raven
 from raven.conf import defaults
 from raven.conf.remote import RemoteConfig
-from raven.context import Context
 from raven.exceptions import APIError, RateLimited
 from raven.utils import json, get_versions, get_auth_header, merge_dicts
 from raven._compat import text_type, iteritems
@@ -133,7 +132,8 @@ class Client(object):
     _registry = TransportRegistry(transports=default_transports)
 
     def __init__(self, dsn=None, raise_send_errors=False, transport=None,
-                 install_sys_hook=True, **options):
+                 install_sys_hook=True, install_logging_hook=True,
+                 hook_libraries=None, **options):
         global Raven
 
         o = options
@@ -186,11 +186,22 @@ class Client(object):
         if Raven is None:
             Raven = self
 
-        self._context = Context()
+        from raven.context import Context
+        self._context = Context(self)
+
+        # We always activate the context for the calling thread.  This
+        # means even in the absence of code that activates the context for
+        # threads otherwise.
+        self._context.activate()
 
         if install_sys_hook:
             self.install_sys_hook()
 
+        if install_logging_hook:
+            self.install_logging_hook()
+
+        self.hook_libraries(hook_libraries)
+
     def set_dsn(self, dsn=None, transport=None):
         if not dsn and os.environ.get('SENTRY_DSN'):
             msg = "Configuring Raven from environment variable 'SENTRY_DSN'"
@@ -224,6 +235,14 @@ class Client(object):
             __excepthook__(*exc_info)
         sys.excepthook = handle_exception
 
+    def install_logging_hook(self):
+        from raven.breadcrumbs import install_logging_hook
+        install_logging_hook()
+
+    def hook_libraries(self, libraries):
+        from raven.breadcrumbs import hook_libraries
+        hook_libraries(libraries)
+
     @classmethod
     def register_scheme(cls, scheme, transport_class):
         cls._registry.register_scheme(scheme, transport_class)
@@ -436,6 +455,15 @@ class Client(object):
         data.setdefault('platform', PLATFORM_NAME)
         data.setdefault('sdk', SDK_VALUE)
 
+        # insert breadcrumbs
+        crumbs = self.context.breadcrumbs.get_buffer()
+        if crumbs:
+            # Make sure we send the crumbs here as "values" as we use the
+            # raven client internally in sentry and the alternative
+            # submission option of a list here is not supported by the
+            # internal sender.
+            data.setdefault('breadcrumbs', {'values': crumbs})
+
         return data
 
     def transform(self, data):
@@ -797,6 +825,17 @@ class Client(object):
             DeprecationWarning)
         return self.context(**kwargs)
 
+    def captureBreadcrumb(self, type, *args, **kwargs):
+        """Records a breadcrumb with the current context.  They will be
+        sent with the next event.
+        """
+        # Note: framework integration should not call this method but
+        # instead use the raven.breadcrumbs.record_breadcrumb function
+        # which will record to the correct client automatically.
+        self.context.breadcrumbs.record(type, *args, **kwargs)
+
+    capture_breadcrumb = captureBreadcrumb
+
 
 class DummyClient(Client):
     "Sends messages into an empty void"
diff --git a/raven/breadcrumbs.py b/raven/breadcrumbs.py
new file mode 100644
index 0000000..2aa44fd
--- /dev/null
+++ b/raven/breadcrumbs.py
@@ -0,0 +1,300 @@
+from __future__ import absolute_import
+
+import time
+import logging
+from types import FunctionType
+
+from raven._compat import iteritems, get_code, text_type, string_types
+from raven.utils import once
+
+
+special_logger_handlers = {}
+
+
+class BreadcrumbBuffer(object):
+
+    def __init__(self, limit=100):
+        self.buffer = []
+        self.limit = limit
+
+    def record(self, type, timestamp=None, duration=None, level=None,
+               message=None, category=None, data=None, processor=None):
+        if timestamp is None:
+            timestamp = time.time()
+        self.buffer.append(({
+            'type': type,
+            'timestamp': timestamp,
+            'duration': duration,
+            'level': level,
+            'message': message,
+            'category': category,
+            'data': data,
+        }, processor))
+        del self.buffer[:-self.limit]
+
+    def clear(self):
+        del self.buffer[:]
+
+    def get_buffer(self):
+        rv = []
+        for idx, (payload, processor) in enumerate(self.buffer):
+            if processor is not None:
+                processor(payload)
+                self.buffer[idx] = (payload, None)
+            rv.append(payload)
+        return rv
+
+
+def record_breadcrumb(type, timestamp=None, duration=None, level=None,
+                      message=None, category=None, data=None,
+                      processor=None):
+    """Records a breadcrumb for all active clients.  This is what integration
+    code should use rather than invoking the `captureBreadcrumb` method
+    on a specific client.
+    """
+    if timestamp is None:
+        timestamp = time.time()
+    for ctx in raven.context.get_active_contexts():
+        ctx.breadcrumbs.record(type, timestamp, duration, level, message,
+                               category, data, processor)
+
+
+def _record_log_breadcrumb(logger, level, msg, *args, **kwargs):
+    handler = special_logger_handlers.get(logger.name)
+    if handler is not None:
+        rv = handler(logger, level, msg, args, kwargs)
+        if rv:
+            return
+
+    def processor(data):
+        formatted_msg = text_type(msg)
+        if args:
+            formatted_msg = msg % args
+        data.update({
+            'message': formatted_msg,
+            'category': logger.name.split('.')[0],
+            'level': logging.getLevelName(level).lower(),
+            'data': kwargs,
+        })
+    record_breadcrumb('default', processor=processor)
+
+
+def _wrap_logging_method(meth, level=None):
+    if not isinstance(meth, FunctionType):
+        func = meth.im_func
+    else:
+        func = meth
+
+    # We were patched for raven before
+    if getattr(func, '__patched_for_raven__', False):
+        return
+
+    if level is None:
+        args = ('level', 'msg')
+        fwd = 'level, msg'
+    else:
+        args = ('msg',)
+        fwd = '%d, msg' % level
+
+    code = get_code(func)
+
+    # 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.__file__, 'exec'), logging.__dict__, ns)
+
+    new_func = ns['factory'](meth, _record_log_breadcrumb)
+    new_func.__doc__ = func.__doc__
+
+    assert code.co_firstlineno == get_code(func).co_firstlineno
+    assert new_func.__module__ == func.__module__
+    assert new_func.__name__ == func.__name__
+    new_func.__patched_for_raven__ = True
+
+    return new_func
+
+
+def _patch_logger():
+    cls = logging.Logger
+
+    methods = {
+        'debug': logging.DEBUG,
+        'info': logging.INFO,
+        'warning': logging.WARNING,
+        'warn': logging.WARN,
+        'error': logging.ERROR,
+        'exception': logging.ERROR,
+        'critical': logging.CRITICAL,
+        'fatal': logging.FATAL
+    }
+
+    for method_name, level in iteritems(methods):
+        new_func = _wrap_logging_method(
+            getattr(cls, method_name), level)
+        setattr(logging.Logger, method_name, new_func)
+
+    logging.Logger.log = _wrap_logging_method(
+        logging.Logger.log)
+
+
+@once
+def install_logging_hook():
+    """Installs the logging hook if it was not installed yet.  Otherwise
+    does nothing.
+    """
+    _patch_logger()
+
+
+def ignore_logger(name_or_logger, allow_level=None):
+    """Ignores a logger for the regular breadcrumb code.  This is useful
+    for framework integration code where some log messages should be
+    specially handled.
+    """
+    def handler(logger, level, msg, args, kwargs):
+        if allow_level is not None and \
+           level >= allow_level:
+            return False
+        return True
+    register_special_log_handler(name_or_logger, handler)
+
+
+def register_special_log_handler(name_or_logger, callback):
+    """Registers a callback for log handling.  The callback is invoked
+    with give arguments: `logger`, `level`, `msg`, `args` and `kwargs`
+    which are the values passed to the logging system.  If the callback
+    returns `True` the default handling is disabled.
+    """
+    if isinstance(name_or_logger, string_types):
+        name = name_or_logger
+    else:
+        name = name_or_logger.name
+    special_logger_handlers[name] = callback
+
+
+hooked_libraries = {}
+
+
+def libraryhook(name):
+    def decorator(f):
+        f = once(f)
+        hooked_libraries[name] = f
+        return f
+    return decorator
+
+
+@libraryhook('requests')
+def _hook_requests():
+    try:
+        from requests.sessions import Session
+    except ImportError:
+        return
+
+    real_send = Session.send
+
+    def send(self, request, *args, **kwargs):
+        def _record_request(response):
+            record_breadcrumb('http', category='requests', data={
+                'url': request.url,
+                'method': request.method,
+                'status_code': response and response.status_code or None,
+                'reason': response and response.reason or None,
+            })
+        try:
+            resp = real_send(self, request, *args, **kwargs)
+        except Exception:
+            _record_request(None)
+            raise
+        else:
+            _record_request(resp)
+        return resp
+
+    Session.send = send
+
+    ignore_logger('requests.packages.urllib3.connectionpool',
+                  allow_level=logging.WARNING)
+
+
+@libraryhook('httplib')
+def _install_httplib():
+    try:
+        from httplib import HTTPConnection
+    except ImportError:
+        from http.client import HTTPConnection
+
+    real_putrequest = HTTPConnection.putrequest
+    real_getresponse = HTTPConnection.getresponse
+
+    def putrequest(self, method, url, *args, **kwargs):
+        self._raven_status_dict = status = {}
+        host = self.host
+        port = self.port
+        default_port = self.default_port
+
+        def processor(data):
+            real_url = url
+            if not real_url.startswith(('http://', 'https://')):
+                real_url = '%s://%s%s%s' % (
+                    default_port == 443 and 'https' or 'http',
+                    host,
+                    port != default_port and ':%s' % port or '',
+                    url,
+                )
+            data['data'] = {
+                'url': real_url,
+                'method': method,
+            }
+            data['data'].update(status)
+            return data
+        record_breadcrumb('http', category='requests',
+                          processor=processor)
+        return real_putrequest(self, method, url, *args, **kwargs)
+
+    def getresponse(self, *args, **kwargs):
+        rv = real_getresponse(self, *args, **kwargs)
+        status = getattr(self, '_raven_status_dict', None)
+        if status is not None and 'status_code' not in status:
+            status['status_code'] = rv.status
+            status['reason'] = rv.reason
+        return rv
+
+    HTTPConnection.putrequest = putrequest
+    HTTPConnection.getresponse = getresponse
+
+
+def hook_libraries(libraries):
+    if libraries is None:
+        libraries = hooked_libraries.keys()
+    for lib in libraries:
+        func = hooked_libraries.get(lib)
+        if func is None:
+            raise RuntimeError('Unknown library %r for hooking' % lib)
+        func()
+
+
+import raven.context
diff --git a/raven/context.py b/raven/context.py
index 6fd7891..cb2efbf 100644
--- a/raven/context.py
+++ b/raven/context.py
@@ -7,36 +7,22 @@ raven.context
 """
 from __future__ import absolute_import
 
-import time
-
 from collections import Mapping, Iterable
-from datetime import datetime
 from threading import local
+from weakref import ref as weakref
 
 from raven._compat import iteritems
 
 
-class BreadcrumbBuffer(object):
-
-    def __init__(self, limit=100):
-        self.buffer = []
-        self.limit = limit
+_active_contexts = local()
 
-    def record(self, type, data=None, timestamp=None):
-        if timestamp is None:
-            timestamp = time.time()
-        elif isinstance(timestamp, datetime):
-            timestamp = datetime
 
-        self.buffer.append({
-            'type': type,
-            'timestamp': timestamp,
-            'data': data or {},
-        })
-        del self.buffer[:-self.limit]
-
-    def clear(self):
-        del self.buffer[:]
+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):
@@ -51,9 +37,29 @@ class Context(local, Mapping, Iterable):
     >>>     finally:
     >>>         context.clear()
     """
-    def __init__(self):
+
+    def __init__(self, client=None):
+        if client is not None:
+            client = weakref(client)
+        self._client = client
         self.data = {}
         self.exceptions_to_skip = set()
+        self.breadcrumbs = raven.breadcrumbs.BreadcrumbBuffer()
+
+    @property
+    def client(self):
+        if self._client is None:
+            return None
+        return self._client()
+
+    def __hash__(self):
+        return id(self)
+
+    def __eq__(self, other):
+        return self is other
+
+    def __ne__(self, other):
+        return not self.__eq__(other)
 
     def __getitem__(self, key):
         return self.data[key]
@@ -67,6 +73,22 @@ class Context(local, Mapping, Iterable):
     def __repr__(self):
         return '<%s: %s>' % (type(self).__name__, self.data)
 
+    def __enter__(self):
+        self.activate()
+        return self
+
+    def __exit__(self, exc_type, exc_value, tb):
+        self.deactivate()
+
+    def activate(self):
+        _active_contexts.__dict__.setdefault('contexts', set()).add(self)
+
+    def deactivate(self):
+        try:
+            _active_contexts.contexts.discard(self)
+        except AttributeError:
+            pass
+
     def merge(self, data):
         d = self.data
         for key, value in iteritems(data):
@@ -83,6 +105,12 @@ class Context(local, Mapping, Iterable):
     def get(self):
         return self.data
 
-    def clear(self):
+    def clear(self, deactivate=True):
         self.data = {}
         self.exceptions_to_skip.clear()
+        self.breadcrumbs.clear()
+        if deactivate:
+            self.deactivate()
+
+
+import raven.breadcrumbs
diff --git a/raven/contrib/django/client.py b/raven/contrib/django/client.py
index 64ece8a..00a555c 100644
--- a/raven/contrib/django/client.py
+++ b/raven/contrib/django/client.py
@@ -1,3 +1,4 @@
+# -*- coding: utf-8 -*-
 """
 raven.contrib.django.client
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~
@@ -8,6 +9,7 @@ raven.contrib.django.client
 
 from __future__ import absolute_import
 
+import time
 import logging
 
 from django.conf import settings
@@ -26,13 +28,115 @@ from raven.base import Client
 from raven.contrib.django.utils import get_data_from_template, get_host
 from raven.contrib.django.middleware import SentryLogMiddleware
 from raven.utils.wsgi import get_headers, get_environ
+from raven.utils import once
+from raven import breadcrumbs
+from raven._compat import string_types, binary_type
 
 __all__ = ('DjangoClient',)
 
 
+class _FormatConverter(object):
+
+    def __init__(self, param_mapping):
+        self.param_mapping = param_mapping
+        self.params = []
+
+    def __getitem__(self, val):
+        self.params.append(self.param_mapping.get(val))
+        return '%s'
+
+
+def format_sql(sql, params):
+    rv = []
+
+    if isinstance(params, dict):
+        conv = _FormatConverter(params)
+        sql = sql % conv
+        params = conv.params
+
+    for param in params or ():
+        if param is None:
+            rv.append('NULL')
+        elif isinstance(param, string_types):
+            if isinstance(param, binary_type):
+                param = param.decode('utf-8', 'replace')
+            if len(param) > 256:
+                param = param[:256] + u'…'
+            rv.append("'%s'" % param.replace("'", "''"))
+        else:
+            rv.append(repr(param))
+
+    return sql, rv
+
+
+@once
+def install_sql_hook():
+    """If installed this causes Django's queries to be captured."""
+    try:
+        from django.db.backends.utils import CursorWrapper
+    except ImportError:
+        from django.db.backends.util import CursorWrapper
+
+    try:
+        real_execute = CursorWrapper.execute
+        real_executemany = CursorWrapper.executemany
+    except AttributeError:
+        # XXX(mitsuhiko): On some very old django versions (<1.6) this
+        # trickery would have to look different but I can't be bothered.
+        return
+
+    def record_sql(vendor, alias, start, duration, sql, params):
+        def processor(data):
+            real_sql, real_params = format_sql(sql, params)
+            if real_params:
+                real_sql = real_sql % tuple(real_params)
+            # maybe category to 'django.%s.%s' % (vendor, alias or
+            #   'default') ?
+            data.update({
+                'message': real_sql,
+                'duration': duration,
+                'category': 'query',
+            })
+        breadcrumbs.record_breadcrumb('default', processor=processor)
+
+    def record_many_sql(vendor, alias, start, sql, param_list):
+        duration = time.time() - start
+        for params in param_list:
+            record_sql(vendor, alias, start, duration, sql, params)
+
+    def execute(self, sql, params=None):
+        start = time.time()
+        try:
+            return real_execute(self, sql, params)
+        finally:
+            record_sql(self.db.vendor, getattr(self.db, 'alias', None),
+                       start, time.time() - start, sql, params)
+
+    def executemany(self, sql, param_list):
+        start = time.time()
+        try:
+            return real_executemany(self, sql, param_list)
+        finally:
+            record_many_sql(self.db.vendor, getattr(self.db, 'alias', None),
+                            start, sql, param_list)
+
+    CursorWrapper.execute = execute
+    CursorWrapper.executemany = executemany
+    breadcrumbs.ignore_logger('django.db.backends')
+
+
 class DjangoClient(Client):
     logger = logging.getLogger('sentry.errors.client.django')
 
+    def __init__(self, *args, **kwargs):
+        install_sql_hook = kwargs.pop('install_sql_hook', True)
+        Client.__init__(self, *args, **kwargs)
+        if install_sql_hook:
+            self.install_sql_hook()
+
+    def install_sql_hook(self):
+        install_sql_hook()
+
     def get_user_info(self, user):
         if hasattr(user, 'is_authenticated') and \
            not user.is_authenticated():
diff --git a/raven/contrib/django/models.py b/raven/contrib/django/models.py
index b2014c9..490978a 100644
--- a/raven/contrib/django/models.py
+++ b/raven/contrib/django/models.py
@@ -181,7 +181,11 @@ def sentry_exception_handler(request=None, **kwargs):
 
 
 def register_handlers():
-    from django.core.signals import got_request_exception
+    from django.core.signals import got_request_exception, request_started
+
+    def before_request(*args, **kwargs):
+        client.context.activate()
+    request_started.connect(before_request, weak=False)
 
     # HACK: support Sentry's internal communication
     if 'sentry' in settings.INSTALLED_APPS:
diff --git a/raven/utils/__init__.py b/raven/utils/__init__.py
index 63f1b81..c22f0bc 100644
--- a/raven/utils/__init__.py
+++ b/raven/utils/__init__.py
@@ -9,6 +9,8 @@ from __future__ import absolute_import
 
 from raven._compat import iteritems, string_types
 import logging
+import threading
+from functools import update_wrapper
 try:
     import pkg_resources
 except ImportError:
@@ -167,3 +169,22 @@ class memoize(object):
         if n not in d:
             d[n] = self.func(obj)
         return d[n]
+
+
+def once(func):
+    """Runs a thing once and once only."""
+    lock = threading.Lock()
+
+    def new_func(*args, **kwargs):
+        if new_func.called:
+            return
+        with lock:
+            if new_func.called:
+                return
+            rv = func(*args, **kwargs)
+            new_func.called = True
+            return rv
+
+    new_func = update_wrapper(new_func, func)
+    new_func.called = False
+    return new_func