Transaction name bleeding between FastAPI requests when using background tasks

[phillipuniverse]

How do you use Sentry?

Sentry Saas (sentry.io)

Version

2.48.0

Steps to Reproduce

Here's a test that illustrates the problem. I kick off 2 background tasks in the /exec-taskgroup request, but the transaction name sent to Sentry is associated with the /request2 request. Here's what the test below simulates:

        parent process      /exec-group             /request2
    1.  GET /exec-group
    2.  --wait--            with task_group():
    3.  --wait--                run errlog1
    4.  --wait--                wake up parent
    5.  GET /request2           --wait--
    6.  --wait--                --wait--            ready to run errlog2
    7.  --wait--                run errlog2         --wait--
    8.  --wait--            return 200              --wait--
    9.  --wait--                                    return 200
    10. verify 200 response
        from GET /exec-group
        and GET /request2
    11. Make assertions

And at the end, I can see that the transaction for "From err1" is /exec-group while the transaction for "From err2" is /request2:

import asyncio
from asyncio import Event
import sentry_sdk

from anyio import create_task_group
from httpx import ASGITransport, AsyncClient
from loguru import logger
from fastapi.application import FastAPI

import dataclasses

from sentry_sdk.types import Event, Hint


@dataclasses.dataclass(kw_only=True, frozen=True)
class BeforeSendCall:
    event: Event
    hint: Hint


class BeforeSendCapturer:
    def __init__(self) -> None:
        self.calls: list[BeforeSendCall] = []

    def reset(self) -> None:
        self.calls.clear()

    def before_send(self, event: Event, hint: Hint) -> Event | None:
        self.calls.append(BeforeSendCall(event=event, hint=hint))
        return event

sentry_before_send_capturer = BeforeSendCapturer()

sentry_sdk.init(...., before_send=sentry_before_send_capturer.before_send)

@pytest.fixture
def sentry_before_send() -> Iterator[BeforeSendCapturer]:
    capturer = sentry_before_send_capturer
    capturer.reset()
    yield capturer
    capturer.reset()


app = FastAPI(title="Integration Tests", version="0.0.1", allowed_hosts=["testserver"])


async def errlog1(executed: Event) -> None:
    logger.info("Running errlog1")
    logger.error("In err1")
    executed.set()


async def errlog2(executed: Event) -> None:
    logger.info("Running errlog2")
    logger.error("In err2")
    executed.set()


async def test_scope_propagated_through_asyncio_taskgroup(sentry_before_send: BeforeSendCapturer) -> None:
    execute_request2, task1_executed, execute_task2, task2_executed, finished = (
        Event(),
        Event(),
        Event(),
        Event(),
        Event(),
    )

    async def errlog1(executed: Event) -> None:
        logger.info("Running errlog1")
        logger.error("From err1")
        executed.set()

    async def errlog2(executed: Event) -> None:
        logger.info("Running errlog2")
        logger.error("From err2")
        executed.set()

    @app.get("/exec-taskgroup")
    async def taskgroup() -> None:
        logger.info("Req taskgroup: starting")
        async with create_task_group() as tg:
            tg.start_soon(errlog1, task1_executed)

            await task1_executed.wait()
            logger.info("Req taskgroup: task1 done, proceed with Req2")
            execute_request2.set()
            logger.info("Req taskgroup: waiting to run task2")
            await execute_task2.wait()

            tg.start_soon(errlog2, task2_executed)
            await task2_executed.wait()

        logger.info("Req taskgroup: task1 and task2 complete, finish request 2")
        finished.set()

    @app.get("/request2")
    async def req2() -> None:
        logger.info("Req2: running, run task 2")
        execute_task2.set()

        await finished.wait()
        logger.info("Req2: completed")

    async def execute_requests(client: AsyncClient) -> None:
        # Execute the first request which starts the first task
        tg_task = asyncio.create_task(client.get("/exec-taskgroup"))
        # wait until task1 is started and ready to execute the 2nd request
        await execute_request2.wait()
        r2_task = asyncio.create_task(client.get("/request2"))

        # wait for both requests to fully complete
        tg_task_response, r2_response = await asyncio.gather(tg_task, r2_task)

        assert tg_task_response.is_success, tg_task_response.text
        assert r2_response.is_success, r2_response.text

    async with (
        AsyncClient(transport=ASGITransport(app=app, raise_app_exceptions=False), base_url="http://test") as client,
    ):
        await execute_requests(client)

    assert len(sentry_before_send.calls) == 2, "Both tasks should have executed and logged an error"

    message_to_transactions = [
        (c.event["logentry"]["message"], c.event["transaction"]) for c in sentry_before_send.calls
    ]
    # TODO: this assertion fails
    assert message_to_transactions == [("From err1", "/exec-taskgroup"), ("From err2", "/exec-taskgroup")], (
        "Both tasks should have the same transaction of /exec-taskgroup"
    )

Expected Result

All tasks executed from a task group share the parent transaction they were executed from

Actual Result

Requests bleed over and tasks from a task group are incorrectly associated with another request

[linear]

PY-2019

[phillipuniverse]

Ok, the key was using the AsyncioIntegration, which is not enabled by default.

This has a side effect that a new span will be started for each task, which may or may not be what you want. In my case it's fine, so the next challenge comes with when and where to call sentry_sdk.init(...) inside of an event loop? I can't call it with asyncio.run() because that will create a new temporary event loop, apply the patching and then just throw the event loop away effectively doing nothing.

In order for all the Sentry SDK monkeypatching to work, I call the sentry_sdk.init(...) within the __init__ for my service's Python module which allows me guarantee the Sentry SDK has applied monkeypatching before any of my imports happen. This is not inside an event loop.

To get this specific behavior inside of an event loop, I added it to the FastAPI lifespan:

@asynccontextmanager
async def lifespan(app: FastAPI) -> AsyncIterator[None]:
    original_task_factory = asyncio.get_running_loop().get_task_factory()

    # Only patch if not already patched
    is_sentry_factory = (
        original_task_factory is not None
        and hasattr(original_task_factory, "__name__")
        and "_sentry_task_factory" in original_task_factory.__name__
    )

    if not is_sentry_factory:
        from sentry_sdk.integrations.asyncio import patch_asyncio  # noqa: PLC0415

        patch_asyncio()  # ensure any background Tasks created carry along the Sentry context

    yield

    # undo whatever Sentry did at the end
    asyncio.get_running_loop().set_task_factory(original_task_factory)


app = FastAPI(lifespan=lifespan)

For the above tests, you need to make sure that the lifespan is correctly invoked. Can be easily done with the asgi-lifespan package and its LifespanManager:

async def test_scope_propagated_through_asyncio_taskgroup(sentry_before_send: BeforeSendCapturer) -> None:
    ...
    ...

    async with (
        LifespanManager(app),
        AsyncClient(transport=ASGITransport(app=app, raise_app_exceptions=False), base_url="http://test") as client,
    ):
        await execute_requests(client)

    # Make sure the tasks are always reported under where the task was executed
    message_to_transactions = [
        (c.event["logentry"]["message"], c.event["transaction"]) for c in sentry_before_send.calls
    ]

    # Success!
    assert message_to_transactions == [("From err1", "/exec-taskgroup"), ("From err2", "/exec-taskgroup")]

this works great!

---

I'm not so sure there's a bug here anymore, although I'm inclined to think there is. Maybe just a documentation update somewhere? I'll keep this open until I hear back from the Sentry team.

[sentrivana]

Hey @phillipuniverse, thanks for raising and for the update as well. I definitely see potential to improve our asyncio support especially with regards to how to set things up. Action items for us that I see:

• Add an option to the AsyncioIntegration to optionally disable task tracking, so that the integration still provides task isolation, but doesn't create spans.
• Improve our documentation wrt to how to enable the integration in circumstances where you don't have a good apparent entry point, see also Support/document initializing SDK when a third-party library controls the asyncio event loop #5149.