bug: tornado "in io loop" logic (python2.7)

[zhammer]

(disclaimer: i don't think this really deserves a fix but want to flag for the team and justify my venturing down this rabbit hole)

bug

discovered some interesting behavior with the tornado stack context for python2.7, where just making a tornado.ioloop.IOLoop in synchronous code destroyed my current ddtrace context.

# python2.7
# ddtrace==0.36.1
# tornado==4.5.3

from __future__ import print_function
from tornado.ioloop import IOLoop
import ddtrace

ddtrace.patch(False, tornado=True)

print("before:", ddtrace.tracer.get_call_context())  # prints a call context
IOLoop.current()
print("after:", ddtrace.tracer.get_call_context())  # prints None

on further investigation i found that a lot of TracerStackContext relies on TracerStackContext._has_io_loop, which according to the documentation should tell us if we're "inside" an event loop:

dd-trace-py/ddtrace/contrib/tornado/stack_context.py

Lines 72 to 74 in 3129a40

	def _has_io_loop(self):
	"""Helper to determine if we are currently in an IO loop"""
	return getattr(IOLoop._current, 'instance', None) is not None

from what i can tell, that logic doesn't check if we're in an event loop, it just checks if there is an event loop. that's why calling IOLoop.current() confuses the script I posted:

• at first there is no event loop, so TracerStackContext thinks we're in synchronous code and grabs a context from threadlocalcontext (which itself creates a context if one doesn't exist)
• after IOLoop.current(), we're still in synchronous code, but there is an event loop so TracerStackContext thinks we're in an event loop and tries to get a context from the tornado state
  • from what i can tell this returns None since we never entered the TracerStackContext

fix attempt

i experimented with a fix here: master...seatgeek:zh-tornado-loop following some discussion on this tornado issue: tornadoweb/tornado#2070

ironically i actually prefer the current behavior (where TracerStackContext always thinks it's in an IOLoop if there is one) so you can more easily do sync -> async propagation like this

@tornado.gen.coroutine
def make_child():
    return self.tracer.trace("child")

with TracerStackContext():
    parent = self.tracer.trace("parent")
    child = tornado.ioloop.IOLoop.current().run_sync(make_child)

assert child.parent_id == parent.span_id

regardless i wanted to raise to you all in case other folks get confused.

[Kyle-Verhoog]

@zhammer thanks for digging into this! Haven't got a chance to read through this thoroughly, but just wanted to give a quick shout-out 😄

It does seem like it's a bug that simply making a new ioloop destroys the current context 😕.

[zhammer]

hey @Kyle-Verhoog ! i just saw this in the 0.37.0 release notes:

Fix task context management for asyncio in Python <3.7 (#1353)

is there a PR that fixed this issue?

[Kyle-Verhoog]

That's so strange that #1353 was included in that line 🤔

We use a script to generate those comments... strange... anyway the corresponding PR should have been #1352.

Sorry about that!

[Kyle-Verhoog]

Thanks again for the report Zach, I'm going to close this issue out as I don't think we're going to get to this with it being a Python 2.7-specific issue. Please reopen if it's something you'd like to addressed!