[tornado] add support for Tornado coroutines and web handlers by palazzem · Pull Request #204 · DataDog/dd-trace-py

palazzem · 2017-03-01T13:33:22Z

What it does

Adds support for the Tornado web framework so that the following is supported:

provide a trace_app() function to automatically trace a Tornado web application
application's handlers must be traced
built-in handlers must be traced (redirect and static handlers)
default error handler must be traced
user defined default handler must be traced
exceptions must be traced
tracer.wrap() decorator must work
trace @run_on_executor
templates (self.render() and UI modules) must be traced (probably this task is delayed)

Docs & Examples

Documentation: http://pypi.datadoghq.com/trace-dev/docs/#module-ddtrace.contrib.tornado
Tornado application that uses coroutines and synchronous calls (PIN object for Redis): tornado trace example trace-examples#18

palazzem · 2017-03-01T13:35:57Z

As stated here: #161 (comment)

This won't work if the caller modifies/sets the callback after wrapping the server with TraceMiddleware. That'd overwrite what's happening below in line 31 and the middleware wouldn't be invoked. That should probably at least be documented if it's not a supported situation.

palazzem · 2017-03-01T13:36:30Z

As stated here: #161 (comment)

The other place where things would want a hook into is Handler._handle_request_exception. It's the only way I could see to get the actual exception information included in the trace. http://www.tornadoweb.org/en/stable/_modules/tornado/web.html & search for def _handle_request_exception. You could potentially use def log_exception if it gets called in all of the needed situations, haven't looked into that. At the very least it seems cleaner given that it's intended to be overridden.

Anyway, the call into on_finish doesn't have enough information to actually grab the details of the exception for inclusion in the span. I was using a dedicated exception tracking system so I didn't get to the point of integrating thais w/APM, but had I not being using the other system I would have been looking for APM to record that information.

palazzem · 2017-03-01T13:44:14Z

Provide a proper documentation and include it in the docs page.

ross

Went ahead and created a trivial example app https://gist.github.com/ross/96e922bfb61323c55b25e6b6e569b9ee that runs though all the sorts of things I'd expect to see/want to do in a real app.

ross · 2017-03-19T05:09:35Z

+            with tracer.trace('tornado.post_notify') as span:
+                # do more work
+
+        @tracer.wrap('tornado.notify', service='tornado-notification')


This will time the generation of the future object (essentially 0s) and not how long the notify method takes to "do something". If instead the put @trace.wrap is on the other side of @tornado.gen.coroutine it'll time things correctly, but not be assigned a parent span id.

actually it should time correctly the function because we're not using the default @tracer.wrap but a special wrapper here. This means that the API is the same as before, but in the case of Tornado we automatically handle the Future monitoring.

We may need to discuss a little bit more on this functionality but the idea is that the API should remain the same.

LotharSee · 2017-03-27T09:04:59Z

+    class MainHandler(tornado.web.RequestHandler):
+        @tornado.gen.coroutine
+        def get(self):
+            ctx = getattr(self.request, 'datadog_context')


About the API

Is that the "best" way we can offer to get the current Context? Is tracer. get_call_context not working here?
We could offer a small helper for that (not to expose this kind of "internal")?

Docs

However, since Context is already a behind-the-scene thing, we might want to remove this part not to confuse the user.
The official standard way is to always use the tracer. I checked the doc and besides for iohttp we never talk about how to get it.
What do you think? If there is no case where getting the context directly is useful,
we should simplify and not talk about how to get it here (but still explain that we attach it to the request object).

About the API, the tracer.get_call_context() can be used and it will work. If it doesn't, it means that ctx = getattr(self.request, 'datadog_context') is wrong too. I attached the context just to use the request as a carrier, but yea... we're using a StackContext to transfer the right context to the right logical execution so this could be seen as redundant.

About docs, if we say: "to retrieve your context you must use our tracer.get_call_context() API", then we can remove any occurrences here. It could also be applied to aiohttp.

Okay cool, probably better that way!

LotharSee · 2017-03-27T09:10:45Z

@@ -0,0 +1,8 @@
+"""
+This module defines Tornado settings that are shared between


We usually refer to settings when it is about configurable options themselves (like the Django settings), while here they are only keys (and not all about settings).
Maybe we could call this constants or something?

yes constants is the right name!

LotharSee · 2017-03-27T09:31:12Z

+        handlers.wrap_methods(default_handler_class)
+        return
+
+    # if a default_handler_class is not defined, it means that the default ErrorHandler is used;


Great comment 👍

LotharSee

Some minor comments, otherwise it looks good! (but I didn't test it since I have no tornado code).

It seems mostly centered on the web framework, will it work well if someone uses just some pieces (like ioloop or coroutines) inside another app (let's say Django)? (not even sure that's legit though).

LotharSee

Besides the minor doc/naming comments, it is good to me.

palazzem · 2017-03-31T11:27:43Z

+
+        span.finish()
+
+def wrap_executor(tracer, fn, args, kwargs, span_name, service, resource, span_type):


as a follow-up of #221 (review) we should update the signature so that this is a valid example for future integrations.

…text object

…nt Thread

…ing implementation

…ermediate wrapper kwargs

…not available

…llocator (#17664) ## Description This PR fixes a segmentation fault in the memory allocation profiler that occurs when a hook call races with `memalloc` start/stop operations. The issue arises from concurrent access to the saved allocator struct, which could be partially written while being read, resulting in`NULL` function pointers being dereferenced. The key indicator in that case is that `#1 0x0000000000000000` frame -- we are trying to execute a null function pointer. ```` Error UnixSignal: Process terminated with SEGV_MAPERR (SIGSEGV) #0 0x00007ff3c303a8d4 #1 0x0000000000000000 memalloc_alloc (/go/src/github.com/DataDog/apm-reliability/dd-trace-py/ddtrace/profiling/collector/_memalloc.cpp:68) #2 0x00007ff39dcb3b20 memalloc_alloc (/go/src/github.com/DataDog/apm-reliability/dd-trace-py/ddtrace/profiling/collector/_memalloc.cpp:68) #3 0x00007ff39dcb3b20 memalloc_malloc(void*, unsigned long) (/go/src/github.com/DataDog/apm-reliability/dd-trace-py/ddtrace/profiling/collector/_memalloc.cpp:80) #4 0x00007ff3c3087e1b PyUnicode_New #5 0x00007ff3c30889f4 #6 0x00007ff3c3170c84 #7 0x00007ff3c316b931 #8 0x00007ff3c31aaac8 #9 0x00007ff3c31033ac #10 0x00007ff3c310e2a6 PyObject_CallMethodObjArgs #11 0x00007ff3c310e46d #12 0x00007ff3c31a96c2 #13 0x00007ff3c3102fd7 PyObject_Vectorcall #14 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #15 0x00007ff3c323c094 #16 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #17 0x00007ff3c323c094 #18 0x00007ff3c30e997d PyObject_CallOneArg #19 0x00007ff3c306a480 _PyObject_GenericGetAttrWithDict #20 0x00007ff3c30c620d PyObject_GetAttr #21 0x00007ff3c32309e7 _PyEval_EvalFrameDefault #22 0x00007ff3c323c094 #23 0x00007ff3c312880e #24 0x00007ff3c30e917c _PyObject_MakeTpCall #25 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #26 0x00007ff3c323c094 #27 0x00007ff3c312880e #28 0x00007ff3c30e917c _PyObject_MakeTpCall #29 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #30 0x00007ff3c323c094 #31 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #32 0x00007ff3c323c094 #33 0x00007ff3c317d0fd #34 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #35 0x00007ff3c323c094 #36 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #37 0x00007ff3c323c094 #38 0x00007ff3c317d1b5 #39 0x00007ff3c3102fd7 PyObject_Vectorcall #40 0x00007ff3c3232f4a _PyEval_EvalFrameDefault #41 0x00007ff3c3240da5 #42 0x00007ff3c324112d #43 0x00007ff3c3233be1 _PyEval_EvalFrameDefault #44 0x00007ff3c323c094 #45 0x00007ff3c317d1b5 #46 0x00007ff3c3102fd7 PyObject_Vectorcall #47 0x00007ff3c3232f4a _PyEval_EvalFrameDefault #48 0x00007ff3c323c094 #49 0x00007ff3c31033ac #50 0x00007ff3c310358d PyObject_CallFunctionObjArgs #51 0x00007ff3bf7eb91d WraptBoundFunctionWrapper_call (/project/src/wrapt/_wrappers.c:3750) #52 0x00007ff3c3104055 _PyObject_Call #53 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #54 0x00007ff3c323c094 #55 0x00007ff3c317d23c #56 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #57 0x00007ff3c323c094 #58 0x00007ff3c310416f _PyObject_Call #59 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #60 0x00007ff3c3240da5 #61 0x00007ff3c324112d #62 0x00007ff3c3233be1 _PyEval_EvalFrameDefault #63 0x00007ff3c323c094 #64 0x00007ff3c317d1b5 #65 0x00007ff3c3102fd7 PyObject_Vectorcall #66 0x00007ff3c3232f4a _PyEval_EvalFrameDefault #67 0x00007ff3c323c094 #68 0x00007ff3c317d1b5 #69 0x00007ff3c310416f _PyObject_Call #70 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #71 0x00007ff3c323c094 #72 0x00007ff3c317d1b5 #73 0x00007ff3c310416f _PyObject_Call #74 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #75 0x00007ff3c323c094 #76 0x00007ff3c31033ac #77 0x00007ff3c310358d PyObject_CallFunctionObjArgs #78 0x00007ff3bf7eb91d WraptBoundFunctionWrapper_call (/project/src/wrapt/_wrappers.c:3750) #79 0x00007ff3c30e917c _PyObject_MakeTpCall #80 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #81 0x00007ff3c323c094 #82 0x00007ff3c317d518 #83 0x00007ff3c3155963 #84 0x00007ff3c315393d #85 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #86 0x00007ff3c323c094 #87 0x00007ff3c317d0fd #88 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #89 0x00007ff3c323c094 #90 0x00007ff3c317d0fd #91 0x00007ff3c317d518 #92 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #93 0x00007ff3c323c094 #94 0x00007ff3c30e9371 _PyObject_FastCallDictTstate #95 0x00007ff3c30e958d _PyObject_Call_Prepend #96 0x00007ff3c3109150 #97 0x00007ff3c3104055 _PyObject_Call #98 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #99 0x00007ff3c323c094 #100 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #101 0x00007ff3c30e958d _PyObject_Call_Prepend #102 0x00007ff3c3109150 #103 0x00007ff3c30e917c _PyObject_MakeTpCall #104 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #105 0x00007ff3c323c094 #106 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #107 0x00007ff3c30e958d _PyObject_Call_Prepend #108 0x00007ff3c3109150 #109 0x00007ff3c30e917c _PyObject_MakeTpCall #110 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #111 0x00007ff3c323c094 #112 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #113 0x00007ff3c30e958d _PyObject_Call_Prepend #114 0x00007ff3c3109150 #115 0x00007ff3c30e917c _PyObject_MakeTpCall #116 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #117 0x00007ff3c323c094 #118 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #119 0x00007ff3c30e958d _PyObject_Call_Prepend #120 0x00007ff3c3109150 #121 0x00007ff3c30e917c _PyObject_MakeTpCall #122 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #123 0x00007ff3c323c094 #124 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #125 0x00007ff3c30e958d _PyObject_Call_Prepend #126 0x00007ff3c3109150 #127 0x00007ff3c30e917c _PyObject_MakeTpCall #128 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #129 0x00007ff3c323c094 #130 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #131 0x00007ff3c30e958d _PyObject_Call_Prepend #132 0x00007ff3c3109150 #133 0x00007ff3c30e917c _PyObject_MakeTpCall #134 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #135 0x00007ff3c323c094 #136 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #137 0x00007ff3c30e958d _PyObject_Call_Prepend #138 0x00007ff3c3109150 #139 0x00007ff3c30e917c _PyObject_MakeTpCall #140 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #141 0x00007ff3c323c094 #142 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #143 0x00007ff3c30e958d _PyObject_Call_Prepend #144 0x00007ff3c3109150 #145 0x00007ff3c30e917c _PyObject_MakeTpCall #146 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #147 0x00007ff3c323c094 #148 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #149 0x00007ff3c30e958d _PyObject_Call_Prepend #150 0x00007ff3c3109150 #151 0x00007ff3c30e917c _PyObject_MakeTpCall #152 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #153 0x00007ff3c323c094 #154 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #155 0x00007ff3c30e958d _PyObject_Call_Prepend #156 0x00007ff3c3109150 #157 0x00007ff3c30e917c _PyObject_MakeTpCall #158 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #159 0x00007ff3c323c094 #160 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #161 0x00007ff3c30e958d _PyObject_Call_Prepend #162 0x00007ff3c3109150 #163 0x00007ff3c30e917c _PyObject_MakeTpCall #164 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #165 0x00007ff3c323c094 #166 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #167 0x00007ff3c30e958d _PyObject_Call_Prepend #168 0x00007ff3c3109150 #169 0x00007ff3c30e917c _PyObject_MakeTpCall #170 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #171 0x00007ff3c323c094 #172 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #173 0x00007ff3c30e958d _PyObject_Call_Prepend #174 0x00007ff3c3109150 #175 0x00007ff3c30e917c _PyObject_MakeTpCall #176 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #177 0x00007ff3c323c094 #178 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #179 0x00007ff3c30e958d _PyObject_Call_Prepend #180 0x00007ff3c3109150 #181 0x00007ff3c30e917c _PyObject_MakeTpCall #182 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #183 0x00007ff3c323c094 #184 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #185 0x00007ff3c30e958d _PyObject_Call_Prepend #186 0x00007ff3c3109150 #187 0x00007ff3c30e917c _PyObject_MakeTpCall #188 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #189 0x00007ff3c323c094 #190 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #191 0x00007ff3c323c094 #192 0x00007ff3c30e92f1 _PyObject_FastCallDictTstate #193 0x00007ff3c30e958d _PyObject_Call_Prepend #194 0x00007ff3c3109150 #195 0x00007ff3c30e917c _PyObject_MakeTpCall #196 0x00007ff3c32335a2 _PyEval_EvalFrameDefault #197 0x00007ff3c323c094 #198 0x00007ff3c317d0fd #199 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #200 0x00007ff3c323c094 #201 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #202 0x00007ff3c323c094 #203 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #204 0x00007ff3c323c094 #205 0x00007ff3c3233dd3 _PyEval_EvalFrameDefault #206 0x00007ff3c323c094 #207 0x00007ff3c317d23c #208 0x00007ff3c31a7ec5 #209 0x00007ff3c301ac77 #210 0x00007ff3c357c573 ```` The fix implements two key changes. 1. **Hook functions (`memalloc_alloc`, `memalloc_realloc`)**: Snapshot the allocator struct locally before use and guard indirect function calls with `NULL` checks. This prevents crashes if a partially-written struct is observed during a start/stop race. 2. **Start/stop operations (`memalloc_start`, `memalloc_stop`)**: Use local variables and single assignments when publishing the allocator struct to `global_memalloc_ctx.pymem_allocator_obj`. This ensures concurrent hook calls observe either the old or new struct, never a partially-written intermediate state. The real root cause is that `PyMem_GetAllocator` is not documented as atomic, and the struct could be read field-by-field while being written to concurrently. By using local copies and single assignments, we ensure atomicity at the C level and prevent observation of inconsistent state. Co-authored-by: thomas.kowalski <thomas.kowalski@datadoghq.com>

palazzem added integrations wip labels Mar 1, 2017

palazzem self-assigned this Mar 1, 2017

palazzem mentioned this pull request Mar 1, 2017

add asynchronous support for the current Tracer #161

Merged

6 tasks

palazzem commented Mar 1, 2017

View reviewed changes

palazzem force-pushed the palazzem/tornado-support branch from ec1584c to 283a484 Compare March 2, 2017 14:07

palazzem modified the milestone: 0.7.0 Mar 9, 2017

palazzem force-pushed the palazzem/tornado-support branch 4 times, most recently from 3c0b8bf to 8fb619f Compare March 13, 2017 09:45

palazzem requested a review from LotharSee March 13, 2017 14:20

palazzem removed the wip label Mar 16, 2017

ross reviewed Mar 19, 2017

View reviewed changes

LotharSee reviewed Mar 27, 2017

View reviewed changes

palazzem modified the milestones: 0.7.0, 0.8.0 Mar 29, 2017

palazzem assigned LotharSee and unassigned palazzem Mar 30, 2017

LotharSee approved these changes Mar 30, 2017

View reviewed changes

palazzem commented Mar 31, 2017

View reviewed changes

palazzem force-pushed the palazzem/tornado-support branch from 4b4b880 to 53402e1 Compare April 3, 2017 09:00

Emanuele Palazzetti added 24 commits April 10, 2017 10:38

[tornado] using the Handler class name instead of the URL as a resource

d14d129

[tornado] prepend the handler module name in the span.resource

8e73355

[docs] improve Tornado docs by removing misleading usage with the Con…

6c92a43

…text object

[tornado] rename settings in constants

a960cfe

[tornado] wrap_executor uses the right signature with kwargs

c352db7

[tornado] fix inconsistent AsyncHTTPClient cache in tests

032618a

[tornado] major refactoring: patch tornado instead of the single app

236be71

[tornado] provide TornadoTestCase for easy testing

0ffa549

[tornado] handle run_on_executor decorator when executed in a differe…

229946b

…nt Thread

[tornado] tracer.wrap() handle Future objects whatever is the underly…

ba8ffee

…ing implementation

[tornado] test parenting when using executors

aacf34c

[tornado] better comments

13bf2a5

[tornado] handle run_on_executor safety

8d37112

[tornado] handle run_on_executor with arguments

0eaeff8

[tornado] add tracer configuration from Tornado settings

815b1c5

[tornado] add docs according to latest API

f2e0330

[tornado] minor on flake

abb2c79

[tornado] add support for Template generation tracing

72a6fc4

[tornado] template tracing supports partials and exceptions

770a86c

[tornado] HTTPError exception with status code 500 is handled

6832be8

[tornado] reload module when patch/unpatch are applied

3d08853

[tornado] run_on_executor decorator passes the context to Tornado int…

0bae27f

…ermediate wrapper kwargs

[tornado] use try-except in test application when decorator kwarg is …

a7a5e08

…not available

[tornado] update docs

7e4353d

palazzem force-pushed the palazzem/tornado-support branch from 1442e5f to 7e4353d Compare April 10, 2017 08:39

palazzem merged commit bb4812f into master Apr 10, 2017

palazzem deleted the palazzem/tornado-support branch April 10, 2017 09:01

		@@ -0,0 +1,8 @@
		"""
		This module defines Tornado settings that are shared between


		span.finish()

		def wrap_executor(tracer, fn, args, kwargs, span_name, service, resource, span_type):

Conversation

palazzem commented Mar 1, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What it does

Docs & Examples

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ross left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

About the API

Docs

Uh oh!

palazzem Mar 30, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

LotharSee Mar 27, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

palazzem Mar 30, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

LotharSee left a comment

Choose a reason for hiding this comment

Uh oh!

LotharSee left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

palazzem commented Mar 1, 2017 •

edited

Loading

palazzem Mar 30, 2017 •

edited

Loading

LotharSee Mar 27, 2017 •

edited

Loading

palazzem Mar 30, 2017 •

edited

Loading