Skip to content

opentelemetry-instrumentation-flask error during _teardown_request if request spawns child threads and copy_current_request_context is used #1653

Closed
@hangonlyra

Description

@hangonlyra

Describe your environment
Python 3.9

opentelemetry-instrumentation-flask==0.36b0
Flask==2.2.2 (but happens on older versions as well)

Steps to reproduce

from concurrent.futures import ThreadPoolExecutor, as_completed
from random import randint

from flask import Flask, copy_current_request_context

from opentelemetry.instrumentation.flask import FlaskInstrumentor

app = Flask(__name__)

def do_random_stuff():
    @copy_current_request_context
    def inner():
        return randint(0, 100)
    return inner

@app.route("/")
def hello_world():
    count = 4
    executor = ThreadPoolExecutor(count)
    futures = []
    for _ in range(count):
        futures.append(executor.submit(do_random_stuff()))

    for future in as_completed(futures):
        print(future.result())

    return "Hello, World!"

FlaskInstrumentor.instrument_app(app)

Run it with
opentelemetry-instrument --traces_exporter console --metrics_exporter console flask run

What is the expected behavior?
Normal Open Telemetry traces being outputted when accessed via HTTP

What is the actual behavior?

[2023-02-09 10:11:16,480] ERROR in app: Exception on / [GET]
Traceback (most recent call last):
  File "~/otelbug/env/lib/python3.9/site-packages/flask/app.py", line 2525, in wsgi_app
    response = self.full_dispatch_request()
  File "~/otelbug/env/lib/python3.9/site-packages/flask/app.py", line 1822, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "~/otelbug/env/lib/python3.9/site-packages/flask/app.py", line 1820, in full_dispatch_request
    rv = self.dispatch_request()
  File "~/otelbug/env/lib/python3.9/site-packages/flask/app.py", line 1796, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
  File "~/otelbug/app.py", line 25, in hello_world
    print(future.result())
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/concurrent/futures/_base.py", line 439, in result
    return self.__get_result()
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/concurrent/futures/_base.py", line 391, in __get_result
    raise self._exception
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "~/otelbug/env/lib/python3.9/site-packages/flask/ctx.py", line 182, in wrapper
    return ctx.app.ensure_sync(f)(*args, **kwargs)
  File "~/otelbug/env/lib/python3.9/site-packages/flask/ctx.py", line 432, in __exit__
    self.pop(exc_value)
  File "~/otelbug/env/lib/python3.9/site-packages/flask/ctx.py", line 399, in pop
    self.app.do_teardown_request(exc)
  File "~/otelbug/env/lib/python3.9/site-packages/flask/app.py", line 2373, in do_teardown_request
    self.ensure_sync(func)(exc)
  File "~/otelbug/env/lib/python3.9/site-packages/opentelemetry/instrumentation/flask/__init__.py", line 441, in _teardown_request
    activation.__exit__(None, None, None)
  File "/Library/Frameworks/Python.framework/Versions/3.9/lib/python3.9/contextlib.py", line 126, in __exit__
    next(self.gen)
ValueError: generator already executing

Additional context
This is very much a corner case.

It happens because of

  1. flask_request_environ[_ENVIRON_ACTIVATION_KEY] = activation in _before_request for opentelemetry.instrumentation.flask
  2. @copy_current_request_context then copies the entire request context into the children thread.
  3. This gets executed on the children threads once all the request context is copied over.
     activation = flask.request.environ.get(_ENVIRON_ACTIVATION_KEY)
     if not activation:
            # This request didn't start a span, maybe because it was created in
            # a way that doesn't run `before_request`, like when it is created
            # with `app.test_request_context`.
            return
    if exc is None:
        activation.__exit__(None, None, None)

A very easy fix is

flask_request_environ[_ENVIRON_ACTIVATION_KEY] = (threading.get_ident(), activation)
...
thread_id, activation = flask.request.environ.get(_ENVIRON_ACTIVATION_KEY)
if not activation or thread_id != threading.get_ident() :
    # This request didn't start a span, maybe because it was created in
    # a way that doesn't run `before_request`, like when it is created
    # with `app.test_request_context`.
    return
if exc is None:
    activation.__exit__(None, None, None)

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions