Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tornado instrumentation closes spans before on_finish is completed. #495

Closed
pitabwire opened this issue May 12, 2021 · 0 comments · Fixed by #499
Closed

Tornado instrumentation closes spans before on_finish is completed. #495

pitabwire opened this issue May 12, 2021 · 0 comments · Fixed by #499
Labels
bug Something isn't working

Comments

@pitabwire
Copy link
Contributor

pitabwire commented May 12, 2021

Ideally all trace spans in a request response cycle should be contained in one span. However because the tornado instrumentation library closes the span before calling the on_finish method. Orphaned spans from any instrumented code in on_finish method are created. Looking at the code a reordering would fix this situation.

Describe your environment

Python 3.8.5

requirements.txt
tornado==6.0.3

#tracing
opentelemetry-api==1.1.0
opentelemetry-sdk==1.1.0
opentelemetry-exporter-zipkin-json
opentelemetry-instrumentation
opentelemetry-instrumentation-dbapi
opentelemetry-instrumentation-tornado
opentelemetry-exporter-gcp-trace==1.0.0rc0

Steps to reproduce
Run the attached app below:

`

import tornado.ioloop
import tornado.web
from opentelemetry import trace
from opentelemetry.trace import SpanKind

from opentelemetry import trace
from opentelemetry.exporter.cloud_trace import CloudTraceSpanExporter
from opentelemetry.exporter.zipkin.json import ZipkinExporter
from opentelemetry.sdk.resources import SERVICE_NAME, Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
ConsoleSpanExporter,
BatchSpanProcessor
)
from opentelemetry.instrumentation.tornado import TornadoInstrumentor

class MainHandler(tornado.web.RequestHandler):

def on_finish(self) -> None:
    with trace.get_tracer(__name__).start_as_current_span("On finish test", kind=SpanKind.CLIENT) as span:
        print("Testing on finish span")

    super(MainHandler, self).on_finish()

def get(self):
    self.write("Hello, world")

def init_tracing(is_deployment):
resource = Resource.create(attributes={SERVICE_NAME: "Profile Service"})
tracer_provider = TracerProvider(resource=resource)
trace.set_tracer_provider(tracer_provider)

if is_deployment:
    span_exporter = CloudTraceSpanExporter()
else:
    # span_exporter = ZipkinExporter()
    span_exporter = ConsoleSpanExporter()

span_processor = BatchSpanProcessor(span_exporter=span_exporter)
trace.get_tracer_provider().add_span_processor(span_processor)

TornadoInstrumentor().instrument()

def make_app():
return tornado.web.Application([
(r"/", MainHandler),
])

if name == "main":

init_tracing(is_deployment=False)
app = make_app()
app.listen(8888)
tornado.ioloop.IOLoop.current().start()

`

What is the expected behavior?
All traces in a request cycle should be contained in one span. However because the tornado instrumentation library closes the span before calling the on_finish method. This causes an orphaned span to be created.

What is the actual behavior?
Tornado instrumentation library should possibly run on_finish method before closing the main trace span

Additional context
I looked at the code and saw the affected part is here . Is there any reason to close the span before the parent on_finish method can be run?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
1 participant