Skip to content

Commit 787b19b

Browse files
pglombardopglombardo
authored
Log spans may not be created when inside of a Flask Error Handler (#172)
* Flask error handling: call original before closing scope * Flask error handling improvements: cleanup and better context mgmt * Update to count new log span * Add special cases for Python 2.7 variations
1 parent a748e5d commit 787b19b

File tree

8 files changed

+431
-134
lines changed

8 files changed

+431
-134
lines changed

‎instana/instrumentation/flask/__init__.py‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,8 @@
1010
# Blinker support is preferred but we do the best we can when it's not available.
1111
#
1212

13+
from . import common
14+
1315
if signals_available is True:
1416
import instana.instrumentation.flask.with_blinker
1517
else:

‎instana/instrumentation/flask/common.py‎

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,29 @@
1+
from __future__ import absolute_import
2+
3+
import wrapt
4+
5+
from ...singletons import tracer
6+
7+
8+
@wrapt.patch_function_wrapper('flask', 'templating._render')
9+
def render_with_instana(wrapped, instance, argv, kwargs):
10+
ctx = argv[1]
11+
12+
# If we're not tracing, just return
13+
if not hasattr(ctx['g'], 'scope'):
14+
return wrapped(*argv, **kwargs)
15+
16+
with tracer.start_active_span("render", child_of=ctx['g'].scope.span) as rscope:
17+
try:
18+
template = argv[0]
19+
20+
rscope.span.set_tag("type", "template")
21+
if template.name is None:
22+
rscope.span.set_tag("name", '(from string)')
23+
else:
24+
rscope.span.set_tag("name", template.name)
25+
26+
return wrapped(*argv, **kwargs)
27+
except Exception as e:
28+
rscope.span.log_exception(e)
29+
raise

‎instana/instrumentation/flask/vanilla.py‎

Lines changed: 55 additions & 42 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
from __future__ import absolute_import
22

3+
import flask
4+
35
import opentracing
46
import opentracing.ext.tags as ext
57
import wrapt
@@ -8,8 +10,6 @@
810
from ...singletons import agent, tracer
911
from ...util import strip_secrets
1012

11-
import flask
12-
1313

1414
def before_request_with_instana(*argv, **kwargs):
1515
try:
@@ -44,79 +44,92 @@ def before_request_with_instana(*argv, **kwargs):
4444

4545

4646
def after_request_with_instana(response):
47+
scope = None
4748
try:
48-
scope = None
49-
5049
# If we're not tracing, just return
5150
if not hasattr(flask.g, 'scope'):
5251
return response
5352

5453
scope = flask.g.scope
55-
span = scope.span
54+
if scope is not None:
55+
span = scope.span
5656

57-
if 500 <= response.status_code <= 511:
58-
span.set_tag("error", True)
59-
ec = span.tags.get('ec', 0)
60-
if ec is 0:
61-
span.set_tag("ec", ec+1)
57+
if 500 <= response.status_code <= 511:
58+
span.set_tag("error", True)
59+
ec = span.tags.get('ec', 0)
60+
if ec is 0:
61+
span.set_tag("ec", ec+1)
6262

63-
span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code))
64-
tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers)
65-
response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id)
63+
span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code))
64+
tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers)
65+
response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id)
6666
except:
6767
logger.debug("Flask after_request", exc_info=True)
6868
finally:
6969
if scope is not None:
7070
scope.close()
71+
flask.g.scope = None
7172
return response
7273

7374

75+
def teardown_request_with_instana(*argv, **kwargs):
76+
"""
77+
In the case of exceptions, after_request_with_instana isn't called
78+
so we capture those cases here.
79+
"""
80+
if hasattr(flask.g, 'scope'):
81+
if flask.g.scope is not None:
82+
if len(argv) > 0 and argv[0] is not None:
83+
scope = flask.g.scope
84+
scope.span.log_exception(argv[0])
85+
scope.span.set_tag(ext.HTTP_STATUS_CODE, 500)
86+
scope.close()
87+
flask.g.scope = None
88+
89+
7490
@wrapt.patch_function_wrapper('flask', 'Flask.handle_user_exception')
7591
def handle_user_exception_with_instana(wrapped, instance, argv, kwargs):
76-
exc = argv[0]
92+
# Call original and then try to do post processing
93+
response = wrapped(*argv, **kwargs)
7794

78-
if hasattr(flask.g, 'scope'):
79-
scope = flask.g.scope
80-
span = scope.span
81-
82-
if not hasattr(exc, 'code'):
83-
span.log_exception(argv[0])
84-
span.set_tag(ext.HTTP_STATUS_CODE, 500)
85-
scope.close()
95+
try:
96+
exc = argv[0]
8697

87-
return wrapped(*argv, **kwargs)
98+
if hasattr(flask.g, 'scope') and flask.g.scope is not None:
99+
scope = flask.g.scope
100+
span = scope.span
88101

102+
if response is not None:
103+
if hasattr(response, 'code'):
104+
status_code = response.code
105+
else:
106+
status_code = response.status_code
89107

90-
@wrapt.patch_function_wrapper('flask', 'templating._render')
91-
def render_with_instana(wrapped, instance, argv, kwargs):
92-
ctx = argv[1]
108+
if 500 <= status_code <= 511:
109+
span.log_exception(exc)
93110

94-
# If we're not tracing, just return
95-
if not hasattr(ctx['g'], 'scope'):
96-
return wrapped(*argv, **kwargs)
111+
span.set_tag(ext.HTTP_STATUS_CODE, int(status_code))
97112

98-
with tracer.start_active_span("render", child_of=ctx['g'].scope.span) as rscope:
99-
try:
100-
template = argv[0]
113+
if hasattr(response, 'headers'):
114+
tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers)
115+
response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id)
101116

102-
rscope.span.set_tag("type", "template")
103-
if template.name is None:
104-
rscope.span.set_tag("name", '(from string)')
105-
else:
106-
rscope.span.set_tag("name", template.name)
107-
return wrapped(*argv, **kwargs)
108-
except Exception as e:
109-
rscope.span.log_exception(e)
110-
raise
117+
scope.close()
118+
flask.g.scope = None
119+
except:
120+
logger.debug("handle_user_exception_with_instana:", exc_info=True)
121+
finally:
122+
return response
111123

112124

113125
@wrapt.patch_function_wrapper('flask', 'Flask.full_dispatch_request')
114126
def full_dispatch_request_with_instana(wrapped, instance, argv, kwargs):
115127
if not hasattr(instance, '_stan_wuz_here'):
116-
logger.debug("Applying flask before/after instrumentation funcs")
128+
logger.debug("Flask(vanilla): Applying flask before/after instrumentation funcs")
117129
setattr(instance, "_stan_wuz_here", True)
118130
instance.after_request(after_request_with_instana)
119131
instance.before_request(before_request_with_instana)
132+
instance.teardown_request(teardown_request_with_instana)
120133
return wrapped(*argv, **kwargs)
121134

122135

‎instana/instrumentation/flask/with_blinker.py‎

Lines changed: 57 additions & 52 deletions
Original file line numberDiff line numberDiff line change
@@ -43,94 +43,99 @@ def request_started_with_instana(sender, **extra):
4343

4444

4545
def request_finished_with_instana(sender, response, **extra):
46+
scope = None
4647
try:
47-
scope = None
48-
49-
# If we're not tracing, just return
5048
if not hasattr(flask.g, 'scope'):
5149
return
5250

5351
scope = flask.g.scope
54-
span = scope.span
52+
if scope is not None:
53+
span = scope.span
5554

56-
if 500 <= response.status_code <= 511:
57-
span.set_tag("error", True)
58-
ec = span.tags.get('ec', 0)
59-
if ec is 0:
60-
span.set_tag("ec", ec+1)
55+
if 500 <= response.status_code <= 511:
56+
span.set_tag("error", True)
57+
ec = span.tags.get('ec', 0)
58+
if ec is 0:
59+
span.set_tag("ec", ec+1)
6160

62-
span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code))
63-
tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers)
64-
response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id)
61+
span.set_tag(ext.HTTP_STATUS_CODE, int(response.status_code))
62+
tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers)
63+
response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id)
6564
except:
6665
logger.debug("Flask after_request", exc_info=True)
6766
finally:
6867
if scope is not None:
6968
scope.close()
70-
return response
7169

7270

7371
def log_exception_with_instana(sender, exception, **extra):
74-
# If we're not tracing, just return
75-
if not hasattr(flask.g, 'scope'):
76-
return
77-
78-
scope = flask.g.scope
79-
80-
if scope is not None:
81-
span = scope.span
82-
if span is not None:
83-
span.log_exception(exception)
72+
if hasattr(flask.g, 'scope') and flask.g.scope is not None:
73+
scope = flask.g.scope
74+
if scope.span is not None:
75+
scope.span.log_exception(exception)
76+
scope.close()
8477

8578

8679
@wrapt.patch_function_wrapper('flask', 'Flask.handle_user_exception')
8780
def handle_user_exception_with_instana(wrapped, instance, argv, kwargs):
88-
exc = argv[0]
8981

90-
if hasattr(flask.g, 'scope'):
91-
scope = flask.g.scope
92-
span = scope.span
82+
# Call original and then try to do post processing
83+
response = wrapped(*argv, **kwargs)
9384

94-
if not hasattr(exc, 'code'):
95-
span.log_exception(exc)
96-
span.set_tag(ext.HTTP_STATUS_CODE, 500)
97-
scope.close()
98-
flask.g.scope = None
85+
try:
86+
exc = argv[0]
9987

100-
return wrapped(*argv, **kwargs)
88+
if hasattr(flask.g, 'scope') and flask.g.scope is not None:
89+
scope = flask.g.scope
90+
span = scope.span
10191

92+
if response is not None:
93+
if hasattr(response, 'code'):
94+
status_code = response.code
95+
else:
96+
status_code = response.status_code
10297

103-
@wrapt.patch_function_wrapper('flask', 'templating._render')
104-
def render_with_instana(wrapped, instance, argv, kwargs):
105-
ctx = argv[1]
98+
if 500 <= status_code <= 511:
99+
span.log_exception(exc)
106100

107-
# If we're not tracing, just return
108-
if not hasattr(ctx['g'], 'scope'):
109-
return wrapped(*argv, **kwargs)
101+
span.set_tag(ext.HTTP_STATUS_CODE, int(status_code))
110102

111-
with tracer.start_active_span("render", child_of=ctx['g'].scope.span) as rscope:
112-
try:
113-
template = argv[0]
103+
if hasattr(response, 'headers'):
104+
tracer.inject(scope.span.context, opentracing.Format.HTTP_HEADERS, response.headers)
105+
response.headers.add('Server-Timing', "intid;desc=%s" % scope.span.context.trace_id)
114106

115-
rscope.span.set_tag("type", "template")
116-
if template.name is None:
117-
rscope.span.set_tag("name", '(from string)')
118-
else:
119-
rscope.span.set_tag("name", template.name)
120-
return wrapped(*argv, **kwargs)
121-
except Exception as e:
122-
rscope.span.log_exception(e)
123-
raise
107+
scope.close()
108+
flask.g.scope = None
109+
return response
110+
except Exception as e:
111+
logger.debug("handle_user_exception_with_instana:", exc_info=True)
112+
113+
114+
def teardown_request_with_instana(*argv, **kwargs):
115+
"""
116+
In the case of exceptions, after_request_with_instana isn't called
117+
so we capture those cases here.
118+
"""
119+
120+
if hasattr(flask.g, 'scope') and flask.g.scope is not None:
121+
if len(argv) > 0 and argv[0] is not None:
122+
scope = flask.g.scope
123+
scope.span.log_exception(argv[0])
124+
scope.span.set_tag(ext.HTTP_STATUS_CODE, 500)
125+
flask.g.scope.close()
126+
flask.g.scope = None
124127

125128

126129
@wrapt.patch_function_wrapper('flask', 'Flask.full_dispatch_request')
127130
def full_dispatch_request_with_instana(wrapped, instance, argv, kwargs):
128131
if not hasattr(instance, '_stan_wuz_here'):
129-
logger.debug("Applying flask before/after instrumentation funcs")
132+
logger.debug("Flask(blinker): Applying flask before/after instrumentation funcs")
130133
setattr(instance, "_stan_wuz_here", True)
131134
got_request_exception.connect(log_exception_with_instana, instance)
132135
request_started.connect(request_started_with_instana, instance)
133136
request_finished.connect(request_finished_with_instana, instance)
137+
instance.teardown_request(teardown_request_with_instana)
138+
134139
return wrapped(*argv, **kwargs)
135140

136141

0 commit comments

Comments
 (0)