Log spans may not be created when inside of a Flask Error Handler

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:

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

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)
 
 

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)