Skip to content

Starlette/Fastapi: endpoint duration includes the duration of background tasks #3023

@valsteen

Description

@valsteen

Which version of dd-trace-py are you using?

ddtrace==0.55.4

Which version of pip are you using?

21.2.4

Which version of the libraries are you using?

fastapi==0.68.2
starlette==0.14.2

How can we reproduce your problem?

this would be a minimal proof of concept app.py, running through ddtrace-run uvicorn app:app

import asyncio

from ddtrace import tracer
from fastapi import FastAPI, BackgroundTasks

app = FastAPI()


async def some_background_task():
    with tracer.start_span("some_background_task", activate=True):
        tracer.context_provider.activate(None)
        await asyncio.sleep(10)


@app.get("/")
async def main(background_tasks: BackgroundTasks):
    background_tasks.add_task(some_background_task)
    return "ok"

What is the result that you get?

The duration of / is reported to be 10s, while the browser immediately receives the response.
some_background_task is also reported with a duration of 10s.

What is the result that you expected?

I would expect that the reported endpoint duration matches the time it took to get the response, and that the background task is reported separately. Please don't mind that tracer.context_provider.activate(None) might be redundant here, adding it here to show what I have tried.

FastAPI's add_task actually comes from starlette https://www.starlette.io/background/

I can understand why the endpoint duration includes the background task, this is the definition of starlette's Response.__call__:

https://github.com/encode/starlette/blob/ada99beee530e7b841ce320bc6e66f6dbd9ad781/starlette/responses.py#L159

    async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
        await send(
            {
                "type": "http.response.start",
                "status": self.status_code,
                "headers": self.raw_headers,
            }
        )
        await send({"type": "http.response.body", "body": self.body})

        if self.background is not None:
            await self.background()

The response header and body is sent, but the function itself is not finished until all background tasks have been processed.

I believe that this is not what users of ddtrace would expect: the background tasks are used to return a response early without waiting for background operations to finish ; the reported endpoint duration should correspond to when the body was sent

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions