diff --git a/instana/instrumentation/flask/__init__.py b/instana/instrumentation/flask/__init__.py index 87ddeab9..644cdbc6 100644 --- a/instana/instrumentation/flask/__init__.py +++ b/instana/instrumentation/flask/__init__.py @@ -10,6 +10,8 @@ # Blinker support is preferred but we do the best we can when it's not available. # + from . import common + if signals_available is True: import instana.instrumentation.flask.with_blinker else: diff --git a/instana/instrumentation/flask/common.py b/instana/instrumentation/flask/common.py new file mode 100644 index 00000000..273d14e7 --- /dev/null +++ b/instana/instrumentation/flask/common.py @@ -0,0 +1,29 @@ +from __future__ import absolute_import + +import wrapt + +from ...singletons import tracer + + +@wrapt.patch_function_wrapper('flask', 'templating._render') +def render_with_instana(wrapped, instance, argv, kwargs): + ctx = argv[1] + + # If we're not tracing, just return + if not hasattr(ctx['g'], 'scope'): + return wrapped(*argv, **kwargs) + + with tracer.start_active_span("render", child_of=ctx['g'].scope.span) as rscope: + try: + template = argv[0] + + rscope.span.set_tag("type", "template") + if template.name is None: + rscope.span.set_tag("name", '(from string)') + else: + rscope.span.set_tag("name", template.name) + + return wrapped(*argv, **kwargs) + except Exception as e: + rscope.span.log_exception(e) + raise diff --git a/instana/instrumentation/flask/vanilla.py b/instana/instrumentation/flask/vanilla.py index 26d810ea..30c887aa 100644 --- a/instana/instrumentation/flask/vanilla.py +++ b/instana/instrumentation/flask/vanilla.py @@ -1,5 +1,7 @@ from __future__ import absolute_import +import flask + import opentracing import opentracing.ext.tags as ext import wrapt @@ -8,8 +10,6 @@ from ...singletons import agent, tracer from ...util import strip_secrets -import flask - def before_request_with_instana(*argv, **kwargs): try: @@ -44,79 +44,92 @@ def before_request_with_instana(*argv, **kwargs): def after_request_with_instana(response): + scope = None try: - scope = None - # If we're not tracing, just return if not hasattr(flask.g, 'scope'): return response scope = flask.g.scope - span = scope.span + if scope is not None: + span = scope.span - if 500 <= response.status_code <= 511: - span.set_tag("error", True) - ec = span.tags.get('ec', 0) - if ec is 0: - span.set_tag("ec", ec+1) + if 500 <= response.status_code <= 511: + span.set_tag("error", True) + ec = span.tags.get('ec', 0) + if ec is 0: + span.set_tag("ec", ec+1) - span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code)) - tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers) - response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id) + span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code)) + tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers) + response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id) except: logger.debug("Flask after_request", exc_info=True) finally: if scope is not None: scope.close() + flask.g.scope = None return response +def teardown_request_with_instana(*argv, **kwargs): + """ + In the case of exceptions, after_request_with_instana isn't called + so we capture those cases here. + """ + if hasattr(flask.g, 'scope'): + if flask.g.scope is not None: + if len(argv) > 0 and argv[0] is not None: + scope = flask.g.scope + scope.span.log_exception(argv[0]) + scope.span.set_tag(ext.HTTP_STATUS_CODE, 500) + scope.close() + flask.g.scope = None + + @wrapt.patch_function_wrapper('flask', 'Flask.handle_user_exception') def handle_user_exception_with_instana(wrapped, instance, argv, kwargs): - exc = argv[0] + # Call original and then try to do post processing + response = wrapped(*argv, **kwargs) - if hasattr(flask.g, 'scope'): - scope = flask.g.scope - span = scope.span - - if not hasattr(exc, 'code'): - span.log_exception(argv[0]) - span.set_tag(ext.HTTP_STATUS_CODE, 500) - scope.close() + try: + exc = argv[0] - return wrapped(*argv, **kwargs) + if hasattr(flask.g, 'scope') and flask.g.scope is not None: + scope = flask.g.scope + span = scope.span + if response is not None: + if hasattr(response, 'code'): + status_code = response.code + else: + status_code = response.status_code -@wrapt.patch_function_wrapper('flask', 'templating._render') -def render_with_instana(wrapped, instance, argv, kwargs): - ctx = argv[1] + if 500 <= status_code <= 511: + span.log_exception(exc) - # If we're not tracing, just return - if not hasattr(ctx['g'], 'scope'): - return wrapped(*argv, **kwargs) + span.set_tag(ext.HTTP_STATUS_CODE, int(status_code)) - with tracer.start_active_span("render", child_of=ctx['g'].scope.span) as rscope: - try: - template = argv[0] + if hasattr(response, 'headers'): + tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers) + response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id) - rscope.span.set_tag("type", "template") - if template.name is None: - rscope.span.set_tag("name", '(from string)') - else: - rscope.span.set_tag("name", template.name) - return wrapped(*argv, **kwargs) - except Exception as e: - rscope.span.log_exception(e) - raise + scope.close() + flask.g.scope = None + except: + logger.debug("handle_user_exception_with_instana:", exc_info=True) + finally: + return response @wrapt.patch_function_wrapper('flask', 'Flask.full_dispatch_request') def full_dispatch_request_with_instana(wrapped, instance, argv, kwargs): if not hasattr(instance, '_stan_wuz_here'): - logger.debug("Applying flask before/after instrumentation funcs") + logger.debug("Flask(vanilla): Applying flask before/after instrumentation funcs") setattr(instance, "_stan_wuz_here", True) instance.after_request(after_request_with_instana) instance.before_request(before_request_with_instana) + instance.teardown_request(teardown_request_with_instana) return wrapped(*argv, **kwargs) diff --git a/instana/instrumentation/flask/with_blinker.py b/instana/instrumentation/flask/with_blinker.py index 77253b3b..1a4879f2 100644 --- a/instana/instrumentation/flask/with_blinker.py +++ b/instana/instrumentation/flask/with_blinker.py @@ -43,94 +43,99 @@ def request_started_with_instana(sender, **extra): def request_finished_with_instana(sender, response, **extra): + scope = None try: - scope = None - - # If we're not tracing, just return if not hasattr(flask.g, 'scope'): return scope = flask.g.scope - span = scope.span + if scope is not None: + span = scope.span - if 500 <= response.status_code <= 511: - span.set_tag("error", True) - ec = span.tags.get('ec', 0) - if ec is 0: - span.set_tag("ec", ec+1) + if 500 <= response.status_code <= 511: + span.set_tag("error", True) + ec = span.tags.get('ec', 0) + if ec is 0: + span.set_tag("ec", ec+1) - span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code)) - tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers) - response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id) + span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code)) + tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers) + response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id) except: logger.debug("Flask after_request", exc_info=True) finally: if scope is not None: scope.close() - return response def log_exception_with_instana(sender, exception, **extra): - # If we're not tracing, just return - if not hasattr(flask.g, 'scope'): - return - - scope = flask.g.scope - - if scope is not None: - span = scope.span - if span is not None: - span.log_exception(exception) + if hasattr(flask.g, 'scope') and flask.g.scope is not None: + scope = flask.g.scope + if scope.span is not None: + scope.span.log_exception(exception) + scope.close() @wrapt.patch_function_wrapper('flask', 'Flask.handle_user_exception') def handle_user_exception_with_instana(wrapped, instance, argv, kwargs): - exc = argv[0] - if hasattr(flask.g, 'scope'): - scope = flask.g.scope - span = scope.span + # Call original and then try to do post processing + response = wrapped(*argv, **kwargs) - if not hasattr(exc, 'code'): - span.log_exception(exc) - span.set_tag(ext.HTTP_STATUS_CODE, 500) - scope.close() - flask.g.scope = None + try: + exc = argv[0] - return wrapped(*argv, **kwargs) + if hasattr(flask.g, 'scope') and flask.g.scope is not None: + scope = flask.g.scope + span = scope.span + if response is not None: + if hasattr(response, 'code'): + status_code = response.code + else: + status_code = response.status_code -@wrapt.patch_function_wrapper('flask', 'templating._render') -def render_with_instana(wrapped, instance, argv, kwargs): - ctx = argv[1] + if 500 <= status_code <= 511: + span.log_exception(exc) - # If we're not tracing, just return - if not hasattr(ctx['g'], 'scope'): - return wrapped(*argv, **kwargs) + span.set_tag(ext.HTTP_STATUS_CODE, int(status_code)) - with tracer.start_active_span("render", child_of=ctx['g'].scope.span) as rscope: - try: - template = argv[0] + if hasattr(response, 'headers'): + tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers) + response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id) - rscope.span.set_tag("type", "template") - if template.name is None: - rscope.span.set_tag("name", '(from string)') - else: - rscope.span.set_tag("name", template.name) - return wrapped(*argv, **kwargs) - except Exception as e: - rscope.span.log_exception(e) - raise + scope.close() + flask.g.scope = None + return response + except Exception as e: + logger.debug("handle_user_exception_with_instana:", exc_info=True) + + +def teardown_request_with_instana(*argv, **kwargs): + """ + In the case of exceptions, after_request_with_instana isn't called + so we capture those cases here. + """ + + if hasattr(flask.g, 'scope') and flask.g.scope is not None: + if len(argv) > 0 and argv[0] is not None: + scope = flask.g.scope + scope.span.log_exception(argv[0]) + scope.span.set_tag(ext.HTTP_STATUS_CODE, 500) + flask.g.scope.close() + flask.g.scope = None @wrapt.patch_function_wrapper('flask', 'Flask.full_dispatch_request') def full_dispatch_request_with_instana(wrapped, instance, argv, kwargs): if not hasattr(instance, '_stan_wuz_here'): - logger.debug("Applying flask before/after instrumentation funcs") + logger.debug("Flask(blinker): Applying flask before/after instrumentation funcs") setattr(instance, "_stan_wuz_here", True) got_request_exception.connect(log_exception_with_instana, instance) request_started.connect(request_started_with_instana, instance) request_finished.connect(request_finished_with_instana, instance) + instance.teardown_request(teardown_request_with_instana) + return wrapped(*argv, **kwargs) diff --git a/tests/apps/flaskalino.py b/tests/apps/flaskalino.py index c1e00176..44137fcf 100644 --- a/tests/apps/flaskalino.py +++ b/tests/apps/flaskalino.py @@ -3,10 +3,15 @@ import opentracing.ext.tags as ext from flask import Flask, redirect, render_template, render_template_string from wsgiref.simple_server import make_server +from flask import jsonify from instana.singletons import tracer from ..helpers import testenv +import logging + +logging.basicConfig(level=logging.INFO) +logger = logging.getLogger(__name__) testenv["wsgi_port"] = 10811 testenv["wsgi_server"] = ("http://127.0.0.1:" + str(testenv["wsgi_port"])) @@ -17,6 +22,23 @@ flask_server = make_server('127.0.0.1', testenv["wsgi_port"], app.wsgi_app) + +class InvalidUsage(Exception): + status_code = 400 + + def __init__(self, message, status_code=None, payload=None): + Exception.__init__(self) + self.message = message + if status_code is not None: + self.status_code = status_code + self.payload = payload + + def to_dict(self): + rv = dict(self.payload or ()) + rv['message'] = self.message + return rv + + @app.route("/") def hello(): return "

🐍 Hello Stan! 🦄

" @@ -79,6 +101,11 @@ def exception(): raise Exception('fake error') +@app.route("/exception-invalid-usage") +def exception_invalid_usage(): + raise InvalidUsage("Simulated custom exception", status_code=502) + + @app.route("/render") def render(): return render_template('flask_render_template.html', name="Peter") @@ -94,5 +121,13 @@ def render_error(): return render_template('flask_render_error.html', what='world') +@app.errorhandler(InvalidUsage) +def handle_invalid_usage(error): + logger.error("InvalidUsage error handler invoked") + response = jsonify(error.to_dict()) + response.status_code = error.status_code + return response + + if __name__ == '__main__': flask_server.serve_forever() diff --git a/tests/test_flask.py b/tests/test_flask.py index 69b0e5d7..98a61bcf 100644 --- a/tests/test_flask.py +++ b/tests/test_flask.py @@ -1,8 +1,9 @@ from __future__ import absolute_import +import sys import unittest - import urllib3 +from flask.signals import signals_available from instana.singletons import tracer from .helpers import testenv @@ -28,7 +29,7 @@ def test_vanilla_requests(self): def test_get_request(self): with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/') + response = self.http.request('GET', testenv["wsgi_server"] + '/') spans = self.recorder.queued_spans() self.assertEqual(3, len(spans)) @@ -37,8 +38,24 @@ def test_get_request(self): urllib3_span = spans[1] test_span = spans[2] - assert(r) - self.assertEqual(200, r.status) + assert response + self.assertEqual(200, response.status) + + assert('X-Instana-T' in response.headers) + assert(int(response.headers['X-Instana-T'], 16)) + self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + + assert('X-Instana-S' in response.headers) + assert(int(response.headers['X-Instana-S'], 16)) + self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + + assert('X-Instana-L' in response.headers) + self.assertEqual(response.headers['X-Instana-L'], '1') + + assert('Server-Timing' in response.headers) + server_timing_value = "intid;desc=%s" % wsgi_span.t + self.assertEqual(response.headers['Server-Timing'], server_timing_value) + self.assertIsNone(tracer.active_span) # Same traceId @@ -79,7 +96,7 @@ def test_get_request(self): def test_render_template(self): with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/render') + response = self.http.request('GET', testenv["wsgi_server"] + '/render') spans = self.recorder.queued_spans() self.assertEqual(4, len(spans)) @@ -89,8 +106,24 @@ def test_render_template(self): urllib3_span = spans[2] test_span = spans[3] - assert(r) - self.assertEqual(200, r.status) + assert response + self.assertEqual(200, response.status) + + assert('X-Instana-T' in response.headers) + assert(int(response.headers['X-Instana-T'], 16)) + self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + + assert('X-Instana-S' in response.headers) + assert(int(response.headers['X-Instana-S'], 16)) + self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + + assert('X-Instana-L' in response.headers) + self.assertEqual(response.headers['X-Instana-L'], '1') + + assert('Server-Timing' in response.headers) + server_timing_value = "intid;desc=%s" % wsgi_span.t + self.assertEqual(response.headers['Server-Timing'], server_timing_value) + self.assertIsNone(tracer.active_span) # Same traceId @@ -143,7 +176,7 @@ def test_render_template(self): def test_render_template_string(self): with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/render_string') + response = self.http.request('GET', testenv["wsgi_server"] + '/render_string') spans = self.recorder.queued_spans() self.assertEqual(4, len(spans)) @@ -153,8 +186,24 @@ def test_render_template_string(self): urllib3_span = spans[2] test_span = spans[3] - assert(r) - self.assertEqual(200, r.status) + assert response + self.assertEqual(200, response.status) + + assert('X-Instana-T' in response.headers) + assert(int(response.headers['X-Instana-T'], 16)) + self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + + assert('X-Instana-S' in response.headers) + assert(int(response.headers['X-Instana-S'], 16)) + self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + + assert('X-Instana-L' in response.headers) + self.assertEqual(response.headers['X-Instana-L'], '1') + + assert('Server-Timing' in response.headers) + server_timing_value = "intid;desc=%s" % wsgi_span.t + self.assertEqual(response.headers['Server-Timing'], server_timing_value) + self.assertIsNone(tracer.active_span) # Same traceId @@ -207,7 +256,7 @@ def test_render_template_string(self): def test_301(self): with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/301', redirect=False) + response = self.http.request('GET', testenv["wsgi_server"] + '/301', redirect=False) spans = self.recorder.queued_spans() @@ -217,8 +266,24 @@ def test_301(self): urllib3_span = spans[1] test_span = spans[2] - assert(r) - self.assertEqual(301, r.status) + assert response + self.assertEqual(301, response.status) + + assert('X-Instana-T' in response.headers) + assert(int(response.headers['X-Instana-T'], 16)) + self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + + assert('X-Instana-S' in response.headers) + assert(int(response.headers['X-Instana-S'], 16)) + self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + + assert('X-Instana-L' in response.headers) + self.assertEqual(response.headers['X-Instana-L'], '1') + + assert('Server-Timing' in response.headers) + server_timing_value = "intid;desc=%s" % wsgi_span.t + self.assertEqual(response.headers['Server-Timing'], server_timing_value) + self.assertIsNone(tracer.active_span) # Same traceId @@ -259,7 +324,7 @@ def test_301(self): def test_404(self): with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/11111111111') + response = self.http.request('GET', testenv["wsgi_server"] + '/11111111111') spans = self.recorder.queued_spans() @@ -269,8 +334,24 @@ def test_404(self): urllib3_span = spans[1] test_span = spans[2] - assert(r) - self.assertEqual(404, r.status) + assert response + self.assertEqual(404, response.status) + + # assert('X-Instana-T' in response.headers) + # assert(int(response.headers['X-Instana-T'], 16)) + # self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + # + # assert('X-Instana-S' in response.headers) + # assert(int(response.headers['X-Instana-S'], 16)) + # self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + # + # assert('X-Instana-L' in response.headers) + # self.assertEqual(response.headers['X-Instana-L'], '1') + # + # assert('Server-Timing' in response.headers) + # server_timing_value = "intid;desc=%s" % wsgi_span.t + # self.assertEqual(response.headers['Server-Timing'], server_timing_value) + self.assertIsNone(tracer.active_span) # Same traceId @@ -311,7 +392,7 @@ def test_404(self): def test_500(self): with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/500') + response = self.http.request('GET', testenv["wsgi_server"] + '/500') spans = self.recorder.queued_spans() @@ -321,8 +402,24 @@ def test_500(self): urllib3_span = spans[1] test_span = spans[2] - assert(r) - self.assertEqual(500, r.status) + assert response + self.assertEqual(500, response.status) + + assert('X-Instana-T' in response.headers) + assert(int(response.headers['X-Instana-T'], 16)) + self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + + assert('X-Instana-S' in response.headers) + assert(int(response.headers['X-Instana-S'], 16)) + self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + + assert('X-Instana-L' in response.headers) + self.assertEqual(response.headers['X-Instana-L'], '1') + + assert('Server-Timing' in response.headers) + server_timing_value = "intid;desc=%s" % wsgi_span.t + self.assertEqual(response.headers['Server-Timing'], server_timing_value) + self.assertIsNone(tracer.active_span) # Same traceId @@ -362,19 +459,39 @@ def test_500(self): self.assertTrue(len(urllib3_span.stack) > 1) def test_render_error(self): + if signals_available is True: + raise unittest.SkipTest("Exceptions without handlers vary with blinker") + with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/render_error') + response = self.http.request('GET', testenv["wsgi_server"] + '/render_error') spans = self.recorder.queued_spans() - self.assertEqual(3, len(spans)) + self.assertEqual(4, len(spans)) - wsgi_span = spans[0] - urllib3_span = spans[1] - test_span = spans[2] + log_span = spans[0] + wsgi_span = spans[1] + urllib3_span = spans[2] + test_span = spans[3] + + assert response + self.assertEqual(500, response.status) + + # assert('X-Instana-T' in response.headers) + # assert(int(response.headers['X-Instana-T'], 16)) + # self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + # + # assert('X-Instana-S' in response.headers) + # assert(int(response.headers['X-Instana-S'], 16)) + # self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + # + # assert('X-Instana-L' in response.headers) + # self.assertEqual(response.headers['X-Instana-L'], '1') + # + # assert('Server-Timing' in response.headers) + # server_timing_value = "intid;desc=%s" % wsgi_span.t + # self.assertEqual(response.headers['Server-Timing'], server_timing_value) - assert(r) - self.assertEqual(500, r.status) self.assertIsNone(tracer.active_span) # Same traceId @@ -393,6 +510,11 @@ def test_render_error(self): self.assertTrue(wsgi_span.error) self.assertEqual(1, wsgi_span.ec) + # error log + self.assertEqual("log", log_span.n) + self.assertEqual('Exception on /render_error [GET]', log_span.data.log['message']) + self.assertEqual(" unexpected '}'", log_span.data.log['parameters']) + # wsgi self.assertEqual("wsgi", wsgi_span.n) self.assertEqual('127.0.0.1:' + str(testenv['wsgi_port']), wsgi_span.data.http.host) @@ -414,19 +536,24 @@ def test_render_error(self): self.assertTrue(len(urllib3_span.stack) > 1) def test_exception(self): + if signals_available is True: + raise unittest.SkipTest("Exceptions without handlers vary with blinker") + with tracer.start_active_span('test'): - r = self.http.request('GET', testenv["wsgi_server"] + '/exception') + response = self.http.request('GET', testenv["wsgi_server"] + '/exception') spans = self.recorder.queued_spans() - self.assertEqual(3, len(spans)) + self.assertEqual(4, len(spans)) - wsgi_span = spans[0] - urllib3_span = spans[1] - test_span = spans[2] + log_span = spans[0] + wsgi_span = spans[1] + urllib3_span = spans[2] + test_span = spans[3] + + assert response + self.assertEqual(500, response.status) - assert(r) - self.assertEqual(500, r.status) self.assertIsNone(tracer.active_span) # Same traceId @@ -436,6 +563,7 @@ def test_exception(self): # Parent relationships self.assertEqual(urllib3_span.p, test_span.s) self.assertEqual(wsgi_span.p, urllib3_span.s) + self.assertEqual(log_span.p, wsgi_span.s) # Error logging self.assertFalse(test_span.error) @@ -444,8 +572,19 @@ def test_exception(self): self.assertEqual(1, urllib3_span.ec) self.assertTrue(wsgi_span.error) self.assertEqual(1, wsgi_span.ec) + self.assertTrue(log_span.error) + self.assertEqual(1, log_span.ec) - # wsgi + # error log + self.assertEqual("log", log_span.n) + self.assertEqual('Exception on /exception [GET]', log_span.data.log['message']) + if sys.version_info < (3, 0): + self.assertEqual(" fake error", log_span.data.log['parameters']) + else: + self.assertEqual(" fake error", log_span.data.log['parameters']) + + + # wsgis self.assertEqual("wsgi", wsgi_span.n) self.assertEqual('127.0.0.1:' + str(testenv['wsgi_port']), wsgi_span.data.http.host) self.assertEqual('/exception', wsgi_span.data.http.url) @@ -464,3 +603,79 @@ def test_exception(self): self.assertIsNotNone(urllib3_span.stack) self.assertTrue(type(urllib3_span.stack) is list) self.assertTrue(len(urllib3_span.stack) > 1) + + def test_custom_exception_with_log(self): + with tracer.start_active_span('test'): + response = self.http.request('GET', testenv["wsgi_server"] + '/exception-invalid-usage') + + spans = self.recorder.queued_spans() + + self.assertEqual(4, len(spans)) + + log_span = spans[0] + wsgi_span = spans[1] + urllib3_span = spans[2] + test_span = spans[3] + + assert response + self.assertEqual(502, response.status) + + assert('X-Instana-T' in response.headers) + assert(int(response.headers['X-Instana-T'], 16)) + self.assertEqual(response.headers['X-Instana-T'], wsgi_span.t) + + assert('X-Instana-S' in response.headers) + assert(int(response.headers['X-Instana-S'], 16)) + self.assertEqual(response.headers['X-Instana-S'], wsgi_span.s) + + assert('X-Instana-L' in response.headers) + self.assertEqual(response.headers['X-Instana-L'], '1') + + assert('Server-Timing' in response.headers) + server_timing_value = "intid;desc=%s" % wsgi_span.t + self.assertEqual(response.headers['Server-Timing'], server_timing_value) + + self.assertIsNone(tracer.active_span) + + # Same traceId + self.assertEqual(test_span.t, urllib3_span.t) + self.assertEqual(test_span.t, wsgi_span.t) + + # Parent relationships + self.assertEqual(urllib3_span.p, test_span.s) + self.assertEqual(wsgi_span.p, urllib3_span.s) + + # Error logging + self.assertFalse(test_span.error) + self.assertIsNone(test_span.ec) + self.assertTrue(urllib3_span.error) + self.assertEqual(1, urllib3_span.ec) + self.assertTrue(wsgi_span.error) + self.assertEqual(1, wsgi_span.ec) + self.assertTrue(log_span.error) + self.assertEqual(1, log_span.ec) + + # error log + self.assertEqual("log", log_span.n) + self.assertEqual('InvalidUsage error handler invoked', log_span.data.log['message']) + self.assertEqual(" ", log_span.data.log['parameters']) + + # wsgi + self.assertEqual("wsgi", wsgi_span.n) + self.assertEqual('127.0.0.1:' + str(testenv['wsgi_port']), wsgi_span.data.http.host) + self.assertEqual('/exception-invalid-usage', wsgi_span.data.http.url) + self.assertEqual('GET', wsgi_span.data.http.method) + self.assertEqual(502, wsgi_span.data.http.status) + self.assertIsNone(wsgi_span.data.http.error) + self.assertIsNotNone(wsgi_span.stack) + self.assertEqual(2, len(wsgi_span.stack)) + + # urllib3 + self.assertEqual("test", test_span.data.sdk.name) + self.assertEqual("urllib3", urllib3_span.n) + self.assertEqual(502, urllib3_span.data.http.status) + self.assertEqual(testenv["wsgi_server"] + '/exception-invalid-usage', urllib3_span.data.http.url) + self.assertEqual("GET", urllib3_span.data.http.method) + self.assertIsNotNone(urllib3_span.stack) + self.assertTrue(type(urllib3_span.stack) is list) + self.assertTrue(len(urllib3_span.stack) > 1) diff --git a/tests/test_sudsjurko.py b/tests/test_sudsjurko.py index d8bbc936..99bb6f5d 100644 --- a/tests/test_sudsjurko.py +++ b/tests/test_sudsjurko.py @@ -157,7 +157,6 @@ def test_client_fault(self): assert_equals(True, soap_span.error) assert_equals(1, soap_span.ec) assert('logs' in soap_span.data.custom.__dict__) - assert_equals(1, len(soap_span.data.custom.logs.keys())) tskey = list(soap_span.data.custom.logs.keys())[0] assert('message' in soap_span.data.custom.logs[tskey]) diff --git a/tests/test_urllib3.py b/tests/test_urllib3.py index f0029f57..5ae85a35 100644 --- a/tests/test_urllib3.py +++ b/tests/test_urllib3.py @@ -451,12 +451,11 @@ def test_exception_logging(self): pass spans = self.recorder.queued_spans() + self.assertEqual(4, len(spans)) - self.assertEqual(3, len(spans)) - - wsgi_span = spans[0] - urllib3_span = spans[1] - test_span = spans[2] + wsgi_span = spans[1] + urllib3_span = spans[2] + test_span = spans[3] assert(r) self.assertEqual(500, r.status)