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

mattalbr commented 1 year ago

Seems like a regression of https://github.com/DataDog/dd-trace-py/issues/3023, at least in our specific setup.

Summary of problem

The duration and body of the trace include the execution time of background tasks in FastAPI/Starlette

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

1.9.3

Which version of pip are you using?

23.1.2

Which libraries and their versions are you using?

This is tough because we don't do version pinning and uninstall pip on the images we push. Here's our devcontainer result which should be pretty close.

python 3.11

aiohttp==3.8.4 aiosignal==1.3.1 alembic==1.10.2 anyio==3.6.2 argcomplete==2.1.1 asn1crypto==1.5.1 astroid==2.15.6 asttokens==2.2.1 async-timeout==4.0.2 asyncpg==0.28.0 asyncstdlib==3.10.5 attrs==22.2.0 backcall==0.2.0 black==23.7.0 bytecode==0.14.0 CacheControl==0.12.11 cachetools==5.3.0 cattrs==22.2.0 certifi==2022.12.7 cffi==1.15.1 charset-normalizer==3.1.0 click==8.1.3 cloud-sql-python-connector==1.2.0 comm==0.1.2 cryptography==39.0.2 datadog-api-client==2.13.2 ddsketch==2.0.4 ddtrace==1.9.3 debugpy==1.6.6 decorator==5.1.1 dill==0.3.6 envier==0.4.0 execnet==1.9.0 executing==1.2.0 fastapi==0.101.0 firebase-admin==6.1.0 frozenlist==1.3.3 future==0.18.3 google-api-core==2.11.0 google-api-python-client==2.80.0 google-auth==2.16.2 google-auth-httplib2==0.1.0 google-auth-oauthlib==1.0.0 google-cloud-appengine-logging==1.3.0 google-cloud-audit-log==0.2.5 google-cloud-bigquery==3.6.0 google-cloud-bigquery-storage==2.20.0 google-cloud-core==2.3.2 google-cloud-firestore==2.10.0 google-cloud-logging==3.5.0 google-cloud-pubsub==2.15.0 google-cloud-secret-manager==2.16.0 google-cloud-storage==2.7.0 google-crc32c==1.5.0 google-resumable-media==2.4.1 googleapis-common-protos==1.58.0 graphql-core==3.2.3 greenlet==2.0.2 grpc-google-iam-v1==0.12.6 grpcio==1.51.3 grpcio-status==1.51.3 gspread==5.7.2 gspread-formatting==1.1.2 h11==0.14.0 httpcore==0.16.3 httplib2==0.21.0 httpx==0.23.3 idna==3.4 importlib-metadata==4.11.1 importlib-resources==5.12.0 iniconfig==2.0.0 ipykernel==6.21.3 ipython==8.11.0 isort==5.12.0 itsdangerous==2.1.2 jedi==0.18.2 Jinja2==3.1.2 jsonschema==4.17.3 jsonschema-spec==0.1.3 jupyter_client==8.0.3 jupyter_core==5.2.0 lazy-object-proxy==1.9.0 Mako==1.2.4 MarkupSafe==2.1.2 matplotlib-inline==0.1.6 mccabe==0.7.0 more-itertools==9.1.0 msgpack==1.0.5 multidict==6.0.4 mypy==1.1.1 mypy-extensions==1.0.0 nest-asyncio==1.5.6 numpy==1.26.0 oauthlib==3.2.2 once-py==0.0.2 openapi-schema-validator==0.3.4 openapi-spec-validator==0.5.1 packaging==23.0 pandas==1.5.3 pandas-stubs==1.5.3.230304 parso==0.8.3 pathable==0.4.3 pathspec==0.11.0 petname==2.6 pexpect==4.8.0 pg8000==1.29.4 phonenumbers==8.13.7 pickleshare==0.7.5 platformdirs==3.1.0 pluggy==1.0.0 portabletext-html==1.1.3 prompt-toolkit==3.0.38 proto-plus==1.22.2 protobuf==4.22.1 psutil==5.9.4 ptyprocess==0.7.0 pure-eval==0.2.2 pyarrow==12.0.0 pyasn1==0.4.8 pyasn1-modules==0.2.8 pycparser==2.21 pydantic==1.10.6 pydantic-sqlalchemy==0.0.9 Pygments==2.14.0 PyJWT==2.6.0 pylint==2.17.5 pyparsing==3.0.9 pyrsistent==0.19.3 pytest==7.2.2 pytest-xdist==3.2.0 python-dateutil==2.8.2 python-multipart==0.0.5 pytz==2022.7.1 PyYAML==6.0 pyzmq==25.0.0 requests==2.28.2 requests-oauthlib==1.3.1 respx==0.20.1 rfc3986==1.5.0 rsa==4.9 scramp==1.4.4 sentinel==0.3.0 six==1.16.0 sniffio==1.3.0 sqladmin==0.14.1 sqlakeyset==2.0.1681021882 SQLAlchemy==1.4.46 sqlalchemy-bigquery==1.6.1 sqlalchemy-stubs==0.4 SQLAlchemy-Utils==0.40.0 sqlparse==0.4.3 stack-data==0.6.2 starlette==0.27.0 starlette-context==0.3.6 strawberry-graphql==0.208.0 strawberry-sqlalchemy-mapper==0.3.0 tenacity==8.2.2 testing.common.database==2.0.3 testing.postgresql==1.3.0 tomlkit==0.11.6 tornado==6.2 traitlets==5.9.0 twilio==7.16.5 types-cachetools==5.3.0.4 types-python-dateutil==2.8.19.10 types-pytz==2022.7.1.2 types-PyYAML==6.0.12.8 types-requests==2.28.11.15 types-urllib3==1.26.25.8 typing_extensions==4.5.0 uritemplate==4.1.1 urllib3==1.26.14 uvicorn==0.21.0 wcwidth==0.2.6 wrapt==1.15.0 WTForms==3.0.1 xmltodict==0.13.0 yarl==1.8.2 zipp==3.15.0

How can we reproduce your problem?

We use: ddtrace-run on Cloud Run We have a sync endpoint /health that looks like:

router = fastapi.APIRouter(prefix="/health", route_class=startup.ContextRouter)

@router.get("/", response_model=bool, include_in_schema=False)
@router.get("", response_model=bool)
def check(background_tasks: fastapi.BackgroundTasks, session=database.Sessioner):
    result = session.execute(sqlalchemy.text("SELECT 1;")).one()
    if len(result) == 1 and result[0] == 1:
        background_tasks.add_task(run_slow_http_request)
        return True
    raise ValueError("Expected to query (1,) but got " + str(result))

def run_slow_http_request():
    httpx.get("https://google.com")

What is the result that you get?

What is the result that you expected?

I expected background tasks to either not be included, or be specifically segmented in the trace.

emmettbutler commented 1 year ago

Thanks for reporting this, @mattalbr.

I think we'll want to look into how this regression test could be adjusted to cover the scenario your code is creating.

mabdinur commented 12 months ago

A potential fix here would be to trace fastapi.BackgroundTasks.add_task(...) and use a span link to connect this span to the fastapi.request.

@emmettbutler I can own this issue

mabdinur commented 12 months ago

Hi @mattalbr,

Sorry for the late reply.

This issue was fixed in ddtrace v1.14.0 (commit). Can you try upgrading to a more recent version of ddtrace?

I opened the following PR to enhance ddtrace support for starlette background tasks: https://github.com/DataDog/dd-trace-py/pull/7618.

DataDog / dd-trace-py