From 8c10386e490dcd812e28b92cdda7ca809db68e47 Mon Sep 17 00:00:00 2001 From: Matt Perpick Date: Wed, 22 Jun 2016 21:02:53 +0000 Subject: [PATCH 1/3] trace/errors: add a way to handle trace errors --- ddtrace/compat.py | 5 +++ ddtrace/contrib/flask/__init__.py | 4 ++- ddtrace/contrib/flask/test_flask.py | 5 ++- ddtrace/contrib/pylons/__init__.py | 4 +-- ddtrace/contrib/sqlite3/test_sqlite3.py | 6 ++++ ddtrace/ext/errors.py | 17 ++++++++++ ddtrace/span.py | 44 ++++++++++++++++++++++--- ddtrace/test_span.py | 27 +++++++++++++++ 8 files changed, 104 insertions(+), 8 deletions(-) create mode 100644 ddtrace/ext/errors.py diff --git a/ddtrace/compat.py b/ddtrace/compat.py index 1155d3cfc82..5771b4cfec8 100644 --- a/ddtrace/compat.py +++ b/ddtrace/compat.py @@ -11,3 +11,8 @@ import simplejson as json except ImportError: import json + +try: + from cStringIO import StringIO +except ImportError: + from StringIO import StringIO diff --git a/ddtrace/contrib/flask/__init__.py b/ddtrace/contrib/flask/__init__.py index eeb42288a8f..c4f0d41d575 100644 --- a/ddtrace/contrib/flask/__init__.py +++ b/ddtrace/contrib/flask/__init__.py @@ -10,7 +10,7 @@ import logging # project -from ...ext import http +from ...ext import http, errors # 3p from flask import g, request, signals @@ -70,6 +70,8 @@ def _finish_span(self, response=None, exception=None): if not response and exception: error = 1 code = 500 + span.set_tag(errors.ERROR_TYPE, type(exception)) + span.set_tag(errors.ERROR_MSG, exception) span.resource = str(request.endpoint or "").lower() span.set_tag(http.URL, str(request.base_url or "")) diff --git a/ddtrace/contrib/flask/test_flask.py b/ddtrace/contrib/flask/test_flask.py index 14f72dd285f..9f011239b1e 100644 --- a/ddtrace/contrib/flask/test_flask.py +++ b/ddtrace/contrib/flask/test_flask.py @@ -9,7 +9,7 @@ from ... import Tracer from ...contrib.flask import TraceMiddleware from ...test_tracer import DummyWriter -from ...ext import http +from ...ext import http, errors log = logging.getLogger(__name__) @@ -227,4 +227,7 @@ def test_fatal(self): assert s.start >= start assert s.duration <= end - start eq_(s.meta.get(http.STATUS_CODE), '500') + assert "ZeroDivisionError" in s.meta.get(errors.ERROR_TYPE) + msg = s.meta.get(errors.ERROR_MSG) + assert "integer division" in msg, msg diff --git a/ddtrace/contrib/pylons/__init__.py b/ddtrace/contrib/pylons/__init__.py index e73231a67ff..8ba9ec51a13 100644 --- a/ddtrace/contrib/pylons/__init__.py +++ b/ddtrace/contrib/pylons/__init__.py @@ -31,9 +31,9 @@ def _start_response(status, *args, **kwargs): try: return self.app(environ, _start_response) - except Exception as e: + except Exception: if span: - span.error = 1 + span.set_traceback() raise finally: if not span: diff --git a/ddtrace/contrib/sqlite3/test_sqlite3.py b/ddtrace/contrib/sqlite3/test_sqlite3.py index 55c3a4e2820..6b4f65b30cc 100644 --- a/ddtrace/contrib/sqlite3/test_sqlite3.py +++ b/ddtrace/contrib/sqlite3/test_sqlite3.py @@ -7,6 +7,7 @@ from ... import Tracer from ...contrib.sqlite3 import connection_factory from ...test_tracer import DummyWriter +from ...ext import errors def test_foo(): writer = DummyWriter() @@ -57,3 +58,8 @@ def test_foo(): eq_(span.meta["sql.query"], q) eq_(span.error, 1) eq_(span.span_type, "sql") + assert span.get_tag(errors.ERROR_STACK) + assert 'OperationalError' in span.get_tag(errors.ERROR_TYPE) + assert 'no such table' in span.get_tag(errors.ERROR_MSG) + + diff --git a/ddtrace/ext/errors.py b/ddtrace/ext/errors.py new file mode 100644 index 00000000000..4194d421a06 --- /dev/null +++ b/ddtrace/ext/errors.py @@ -0,0 +1,17 @@ +""" +tags for common error attributes +""" + +import traceback + + +ERROR_MSG = "error.msg" # a string representing the error message +ERROR_TYPE = "error.type" # a string representing the type of the error +ERROR_STACK = "error.stack" # a human readable version of the stack. beta. + +def get_traceback(tb=None, error=None): + t = None + if error: + t = type(error) + lines = traceback.format_exception(t, error, tb, limit=20) + return "\n".join(lines) diff --git a/ddtrace/span.py b/ddtrace/span.py index 24134e35d5e..de8ef6cec70 100644 --- a/ddtrace/span.py +++ b/ddtrace/span.py @@ -1,7 +1,12 @@ +from compat import StringIO import logging import random +import sys import time +import traceback + +from .ext import errors log = logging.getLogger(__name__) @@ -112,6 +117,35 @@ def set_tags(self, tags): set_meta = set_tag set_metas = set_tags + def set_traceback(self): + """ If the current stack has a traceback, tag the span with the + relevant error info. + + >>> span.set_traceback() + + is equivalent to: + + >>> exc = sys.exc_info() + >>> span.set_exc_info(*exc) + """ + (exc_type, exc_val, exc_tb) = sys.exc_info() + self.set_exc_info(exc_type, exc_val, exc_tb) + + def set_exc_info(self, exc_type, exc_val, exc_tb): + """ Tag the span with an error tuple as from `sys.exc_info()`. """ + if not (exc_type and exc_val and exc_tb): + return # nothing to do + self.error = 1 + + # get the traceback + buff = StringIO() + traceback.print_exception(exc_type, exc_val, exc_tb, file=buff, limit=20) + tb = buff.getvalue() + + self.set_tag(errors.ERROR_MSG, exc_val) + self.set_tag(errors.ERROR_TYPE, exc_type) + self.set_tag(errors.ERROR_STACK, tb) + def pprint(self): """ Return a human readable version of the span. """ lines = [ @@ -133,10 +167,12 @@ def __enter__(self): return self def __exit__(self, exc_type, exc_val, exc_tb): - if exc_type: - self.error = 1 - # FIXME[matt] store traceback info - self.finish() + try: + if exc_type: + self.set_exc_info(exc_type, exc_val, exc_tb) + self.finish() + except Exception: + log.exception("error closing trace") def __repr__(self): return "" % ( diff --git a/ddtrace/test_span.py b/ddtrace/test_span.py index b12d12e9150..12cf3dec8cb 100644 --- a/ddtrace/test_span.py +++ b/ddtrace/test_span.py @@ -3,6 +3,7 @@ from nose.tools import eq_ from .span import Span +from .ext import errors def test_ids(): @@ -56,6 +57,28 @@ def test_finish(): s2 = Span(tracer=None, name="foo") s2.finish() +def test_traceback_with_error(): + s = Span(None, "foo") + try: + 1/0 + except ZeroDivisionError: + s.set_traceback() + else: + pass + + assert s.error + assert 'by zero' in s.get_tag(errors.ERROR_MSG) + assert "ZeroDivisionError" in s.get_tag(errors.ERROR_TYPE) + assert s.get_tag(errors.ERROR_STACK) + +def test_traceback_without_error(): + s = Span(None, "foo") + s.set_traceback() + assert not s.error + assert not s.get_tag(errors.ERROR_MSG) + assert not s.get_tag(errors.ERROR_TYPE) + assert not s.get_tag(errors.ERROR_STACK) + def test_ctx_mgr(): dt = DummyTracer() s = Span(dt, "bar") @@ -71,6 +94,10 @@ def test_ctx_mgr(): eq_(out, e) assert s.duration > 0, s.duration assert s.error + eq_(s.get_tag(errors.ERROR_MSG), "boo") + assert "Exception" in s.get_tag(errors.ERROR_TYPE) + assert s.get_tag(errors.ERROR_STACK) + else: assert 0, "should have failed" From ebe6900d719e17ba4924ab099d521038ae512c2b Mon Sep 17 00:00:00 2001 From: Matt Perpick Date: Wed, 22 Jun 2016 21:12:48 +0000 Subject: [PATCH 2/3] fix test. --- ddtrace/test_span.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ddtrace/test_span.py b/ddtrace/test_span.py index 12cf3dec8cb..62b3e059296 100644 --- a/ddtrace/test_span.py +++ b/ddtrace/test_span.py @@ -64,7 +64,7 @@ def test_traceback_with_error(): except ZeroDivisionError: s.set_traceback() else: - pass + assert 0, "should have failed" assert s.error assert 'by zero' in s.get_tag(errors.ERROR_MSG) From 8692a5c814e2f3875626ae11e0e1330ce2a0d704 Mon Sep 17 00:00:00 2001 From: Matt Perpick Date: Thu, 23 Jun 2016 17:50:38 +0000 Subject: [PATCH 3/3] errors: readable error type --- ddtrace/span.py | 6 +++++- ddtrace/test_span.py | 2 +- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/ddtrace/span.py b/ddtrace/span.py index de8ef6cec70..9f88de460c7 100644 --- a/ddtrace/span.py +++ b/ddtrace/span.py @@ -135,6 +135,7 @@ def set_exc_info(self, exc_type, exc_val, exc_tb): """ Tag the span with an error tuple as from `sys.exc_info()`. """ if not (exc_type and exc_val and exc_tb): return # nothing to do + self.error = 1 # get the traceback @@ -142,8 +143,11 @@ def set_exc_info(self, exc_type, exc_val, exc_tb): traceback.print_exception(exc_type, exc_val, exc_tb, file=buff, limit=20) tb = buff.getvalue() + # readable version of type (e.g. exceptions.ZeroDivisionError) + exc_type_str = "%s.%s" % (exc_type.__module__, exc_type.__name__) + self.set_tag(errors.ERROR_MSG, exc_val) - self.set_tag(errors.ERROR_TYPE, exc_type) + self.set_tag(errors.ERROR_TYPE, exc_type_str) self.set_tag(errors.ERROR_STACK, tb) def pprint(self): diff --git a/ddtrace/test_span.py b/ddtrace/test_span.py index 62b3e059296..d5bde66df40 100644 --- a/ddtrace/test_span.py +++ b/ddtrace/test_span.py @@ -68,7 +68,7 @@ def test_traceback_with_error(): assert s.error assert 'by zero' in s.get_tag(errors.ERROR_MSG) - assert "ZeroDivisionError" in s.get_tag(errors.ERROR_TYPE) + eq_("exceptions.ZeroDivisionError", s.get_tag(errors.ERROR_TYPE)) assert s.get_tag(errors.ERROR_STACK) def test_traceback_without_error():