ext-flask: flask.copy_current_request_context breaks span

[kaos]

Describe your environment
$ python --version
Python 3.7.5

opentelemetry-api 0.3a0
opentelemetry-ext-flask 0.3a0
opentelemetry-ext-jaeger 0.3a0
opentelemetry-ext-wsgi 0.3a0
opentelemetry-sdk 0.3a0

Not fixed in latest master, as of today:
https://github.com/open-telemetry/opentelemetry-python/blob/4458698ea178498f7af2d476644b34afcc366335/ext/opentelemetry-ext-flask/src/opentelemetry/ext/flask/__init__.py#L83

Steps to reproduce

from flask import Flask, copy_current_request_context
from opentelemetry.ext.flask import instrument_app
from opentelemetry import trace
from opentelemetry.context import Context
from opentelemetry.sdk.trace import Tracer
from opentelemetry.sdk.trace.export import ConsoleSpanExporter
from opentelemetry.sdk.trace.export import SimpleExportSpanProcessor

trace.set_preferred_tracer_implementation(lambda T: Tracer())
span_exporter = ConsoleSpanExporter()
trace.tracer().add_span_processor(SimpleExportSpanProcessor(span_exporter))

app = Flask(__name__)
instrument_app(app)

@app.route("/")
def hello():
    @copy_current_request_context
    def nest():
        return "Hello!"

    return nest()

if __name__ == "__main__":
    app.run(debug=True)

What is the expected behavior?

Span(name="hello", context=SpanContext(trace_id=0x5f518f71873e44725041844a36ccc493, span_id=0xf198dc7dbbf56851, trace_state={}), kind=SpanKind.SERVER, parent=None, start_time=2019-12-30T10:35:25.124501Z, end_time=2019-12-30T10:35:25.125568Z)
127.0.0.1 - - [30/Dec/2019 11:35:25] "GET / HTTP/1.1" 200 -

What is the actual behavior?

Span(name="hello", context=SpanContext(trace_id=0x5f518f71873e44725041844a36ccc493, span_id=0xf198dc7dbbf56851, trace_state={}), kind=SpanKind.SERVER, parent=None, start_time=2019-12-30T10:35:25.124501Z, end_time=2019-12-30T10:35:25.125568Z)
Setting attribute on ended span.
Setting attribute on ended span.
Calling set_status() on an ended span.
127.0.0.1 - - [30/Dec/2019 11:35:25] "GET / HTTP/1.1" 200 -

Additional context

The example to reproduce doesn't make much sense, as to why use the copy request decorator, but in a real application, it is needed when working in a multithreaded environment.

I notice there is a lot of functional overlap with the wsgi version, wouldn't it be feasible to rely more on the wsgi implementation, and simply add the extra flask specific information on top of that?

Note, that the wsgi implementation does not suffer from this issue.

[toumorokoshi]

Thanks for the bug report! I was able to reproduce your example.

I think your suggestion is reasonable, and does avoid the situation where a copied flask context is reused. I did a quick POC that works fine, from what I can tell.

This does introduce two ramifications I want to call out:

1. this will rely on the wsgi timings instead of the flask timings for start/end time. The two seem to be virtually identical.
2. this will require one named tracer to rely on another. namely, the flask trace will have to add metadata to the opentelemetry.ext.wsgi trace, which is quite tricky as one would also have to extract the version of the wsgi extension to get the named tracer appropriately.

This furthers a concept I've been calling out where we probably shouldn't have more than one active span per context. Then one could just get the current span and go from there.

Adding @Oberon00 since he did the bulk of the work here.

[mauriciovasquezbernal]

@toumorokoshi fixed by open-telemetry/opentelemetry-python#370?

[kaos]

open-telemetry/opentelemetry-python#370 is not merged, seems its been put on hold for now: open-telemetry/opentelemetry-python#370 (comment)

[mauriciovasquezbernal]

ops sorry, no idea what I saw...

[Oberon00]

Probably this depends a bit on open-telemetry/opentelemetry-specification#506

[toumorokoshi]

For open-telemetry/opentelemetry-python#370 yes, but there's probably a way we can still enable this without the use of trace.UpdateName.

It's a bit busy right now, but I'll see if I can take another crack at this.

[lzchen]

@toumorokoshi
Is this issue being worked on?

[toumorokoshi]

No, sorry about that. I'll remove myself.

FWIW this is a much easier argument now that updateName can be used liberally (the warning was removed instead with a caveat about the impact on samplers). So we can indeed refactor flask to use wsgi and just update the name.

[github-actions]

This issue was marked stale due to lack of activity. It will be closed in 30 days.