From c47c2278a99470f12dd60caf92fa39e3b34a15a7 Mon Sep 17 00:00:00 2001 From: Alex Boten Date: Fri, 28 Aug 2020 08:42:21 -0700 Subject: [PATCH 1/3] format tracebacks with cause This reverts commit 84e00eb010f7bf1f73656c115e95d20dd7f0df07. --- lightstep/recorder.py | 8 ++++++-- lightstep/util.py | 4 ++-- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/lightstep/recorder.py b/lightstep/recorder.py index 1e06282..9bedbee 100644 --- a/lightstep/recorder.py +++ b/lightstep/recorder.py @@ -14,7 +14,7 @@ import warnings from basictracer.recorder import SpanRecorder -from opentracing.logs import ERROR_KIND, STACK +from opentracing.logs import ERROR_KIND, STACK, ERROR_OBJECT from lightstep.http_converter import HttpConverter from lightstep.thrift_converter import ThriftConverter @@ -171,7 +171,11 @@ def _normalize_log(self, log): log.key_values[ERROR_KIND] = util._format_exc_type(log.key_values[ERROR_KIND]) if STACK in log.key_values: - log.key_values[STACK] = util._format_exc_tb(log.key_values[STACK]) + log.key_values[STACK] = util._format_exc_tb( + log.key_values.get(ERROR_OBJECT), + log.key_values.get(ERROR_KIND), + log.key_values[STACK] + ) return log diff --git a/lightstep/util.py b/lightstep/util.py index 50b61d3..33c403e 100755 --- a/lightstep/util.py +++ b/lightstep/util.py @@ -105,9 +105,9 @@ def _coerce_to_unicode(val): return '(encoding error)' -def _format_exc_tb(exc_tb): +def _format_exc_tb(exc_value, exc_type, exc_tb): if type(exc_tb) is types.TracebackType: - return ''.join(traceback.format_tb(exc_tb)) + return ''.join(traceback.format_exception(exc_value, exc_type, exc_tb)) return exc_tb From 12ec4432871c390248fca08175ac0149f145a448 Mon Sep 17 00:00:00 2001 From: Alex Boten Date: Fri, 28 Aug 2020 13:29:39 -0700 Subject: [PATCH 2/3] adding test cases around error formatting --- tests/recorder_test.py | 75 +++++++++++++++++++++++++++++++++++++++--- 1 file changed, 70 insertions(+), 5 deletions(-) diff --git a/tests/recorder_test.py b/tests/recorder_test.py index b8d4163..247b696 100644 --- a/tests/recorder_test.py +++ b/tests/recorder_test.py @@ -1,13 +1,13 @@ import socket +import sys import time -import unittest import lightstep.constants import lightstep.recorder import lightstep.tracer -import lightstep.recorder from basictracer.span import BasicSpan from basictracer.context import SpanContext +from opentracing.logs import ERROR_KIND, STACK, ERROR_OBJECT import pytest from lightstep.crouton import ttypes @@ -80,9 +80,7 @@ def test_default_tags_set_correctly(recorder): "access_token": "{your_access_token}", "component_name": "python/runtime_test", "periodic_flush_seconds": 0, - "tags": { - "lightstep.hostname": "hostname", - }, + "tags": {"lightstep.hostname": "hostname",}, } new_recorder = lightstep.recorder.Recorder(**runtime_args) for tag in new_recorder._runtime.tags: @@ -179,3 +177,70 @@ def dummy_basic_span(recorder, i): ) span.finish() return span + + +def test_exception_formatting(recorder): + mock_connection = MockConnection() + mock_connection.open() + + assert len(recorder._span_records) == 0 + + span = BasicSpan( + lightstep.tracer._LightstepTracer(False, recorder, None), + operation_name="exception span", + context=SpanContext(trace_id=1000, span_id=2000), + start_time=time.time() - 100, + ) + span.log_kv({ERROR_KIND: AttributeError}) + span.finish() + assert len(recorder._span_records) == 1 + assert recorder.flush(mock_connection) + spans = recorder.converter.get_span_records(mock_connection.reports[0]) + if hasattr(spans[0], "log_records"): + assert len(spans[0].log_records) == 1 + assert len(spans[0].log_records[0].fields) == 1 + assert spans[0].log_records[0].fields[0] == ttypes.KeyValue( + Key="error.kind", Value="AttributeError" + ) + else: + assert len(spans[0].logs) == 1 + assert len(spans[0].logs[0].fields) == 1 + assert spans[0].logs[0].fields[0].key == "error.kind" + assert spans[0].logs[0].fields[0].string_value == "AttributeError" + + span = BasicSpan( + lightstep.tracer._LightstepTracer(False, recorder, None), + operation_name="exception span", + context=SpanContext(trace_id=1000, span_id=2000), + start_time=time.time() - 100, + ) + + try: + raise Exception + except Exception: # pylint: disable=broad-except + exc_type, exc_value, exc_tb = sys.exc_info() + span.log_kv({STACK: exc_tb, ERROR_KIND: exc_type, ERROR_OBJECT: exc_value}) + + span.finish() + assert len(recorder._span_records) == 1 + assert recorder.flush(mock_connection) + spans = recorder.converter.get_span_records(mock_connection.reports[1]) + if hasattr(spans[0], "log_records"): + assert len(spans[0].log_records) == 1 + assert len(spans[0].log_records[0].fields) == 3 + assert spans[0].log_records[0].fields[0].Key == "stack" + assert spans[0].log_records[0].fields[1] == ttypes.KeyValue( + Key="error.kind", Value="Exception" + ) + assert spans[0].log_records[0].fields[2] == ttypes.KeyValue( + Key="error.object", Value="" + ) + else: + assert len(spans[0].logs) == 1 + assert len(spans[0].logs[0].fields) == 3 + assert spans[0].logs[0].fields[0].key == "stack" + assert spans[0].logs[0].fields[1].key == "error.kind" + assert spans[0].logs[0].fields[1].string_value == "Exception" + assert spans[0].logs[0].fields[2].key == "error.object" + assert spans[0].logs[0].fields[2].string_value == "" + From a60594449264bd7bd80df2eb7f97da7bbc9a283a Mon Sep 17 00:00:00 2001 From: Alex Boten Date: Fri, 28 Aug 2020 13:47:55 -0700 Subject: [PATCH 3/3] fix bug --- lightstep/recorder.py | 2 +- lightstep/util.py | 4 ++-- tests/recorder_test.py | 32 ++++++++++++++++++++------------ 3 files changed, 23 insertions(+), 15 deletions(-) diff --git a/lightstep/recorder.py b/lightstep/recorder.py index 9bedbee..fb41b39 100644 --- a/lightstep/recorder.py +++ b/lightstep/recorder.py @@ -172,8 +172,8 @@ def _normalize_log(self, log): if STACK in log.key_values: log.key_values[STACK] = util._format_exc_tb( - log.key_values.get(ERROR_OBJECT), log.key_values.get(ERROR_KIND), + log.key_values.get(ERROR_OBJECT), log.key_values[STACK] ) diff --git a/lightstep/util.py b/lightstep/util.py index 33c403e..aa710e0 100755 --- a/lightstep/util.py +++ b/lightstep/util.py @@ -105,9 +105,9 @@ def _coerce_to_unicode(val): return '(encoding error)' -def _format_exc_tb(exc_value, exc_type, exc_tb): +def _format_exc_tb(exc_type, exc_value, exc_tb): if type(exc_tb) is types.TracebackType: - return ''.join(traceback.format_exception(exc_value, exc_type, exc_tb)) + return ''.join(traceback.format_exception(exc_type, exc_value, exc_tb)) return exc_tb diff --git a/tests/recorder_test.py b/tests/recorder_test.py index 247b696..2daadec 100644 --- a/tests/recorder_test.py +++ b/tests/recorder_test.py @@ -225,22 +225,30 @@ def test_exception_formatting(recorder): assert len(recorder._span_records) == 1 assert recorder.flush(mock_connection) spans = recorder.converter.get_span_records(mock_connection.reports[1]) + if hasattr(spans[0], "log_records"): assert len(spans[0].log_records) == 1 assert len(spans[0].log_records[0].fields) == 3 - assert spans[0].log_records[0].fields[0].Key == "stack" - assert spans[0].log_records[0].fields[1] == ttypes.KeyValue( - Key="error.kind", Value="Exception" - ) - assert spans[0].log_records[0].fields[2] == ttypes.KeyValue( - Key="error.object", Value="" - ) + for field in spans[0].log_records[0].fields: + if field.Key == "stack": + assert "Traceback (most recent call last):" in field.Value + elif field.Key == "error.kind": + assert field.Value == "Exception" + elif field.Key == "error.object": + assert field.Value == "" + else: + raise AttributeError("unexpected field: %s".format(field.Key)) else: assert len(spans[0].logs) == 1 assert len(spans[0].logs[0].fields) == 3 - assert spans[0].logs[0].fields[0].key == "stack" - assert spans[0].logs[0].fields[1].key == "error.kind" - assert spans[0].logs[0].fields[1].string_value == "Exception" - assert spans[0].logs[0].fields[2].key == "error.object" - assert spans[0].logs[0].fields[2].string_value == "" + + for field in spans[0].logs[0].fields: + if field.key == "stack": + assert "Traceback (most recent call last):" in field.string_value + elif field.key == "error.kind": + assert field.string_value == "Exception" + elif field.key == "error.object": + assert field.string_value == "" + else: + raise AttributeError("unexpected field: %s".format(field.key))