fix(asgi, starlette, fastapi): exclude background task durations from web requests #3799

wantsui · 2022-06-07T22:52:45Z

Following up on #3023, currently libraries traced via the asgi integration, such asfastapi.request and starlette.request spans include the duration of background tasks. This PR updates the asgi middleware code so that spans end earlier by excluding background tasks to better represent the web requests response times.

Current Behavior
$$\begin{align}duration = {http response time} + {background tasks time}\end{align}$$

What it looks like with the PR
$$\begin{align}duration = {http response time}\end{align}$$

Example: An application return a "hello world!" to the user in $2 milliseconds$, but the events that happen in the background lasts another $8 seconds$.

With this PR, the span will report a duration of $2 milliseconds$, instead of $2 milliseconds + 8 seconds$.

Fixes #3023

Also fixes this failing test: https://app.circleci.com/pipelines/github/DataDog/dd-trace-py/18150/workflows/24caa985-5805-4bff-a4eb-5b143f24a2fb/jobs/1233079

Checklist

Library documentation is updated.
Corp site documentation is updated (link to the PR).

Reviewer Checklist

ddtrace/contrib/asgi/middleware.py

mergify · 2022-06-12T20:07:26Z

@wantsui this pull request is now in conflict 😩

tests/contrib/fastapi/test_fastapi.py

tests/contrib/starlette/test_starlette.py

…d fail.

…e, and fastapi. Update the releases for the change.

mabdinur

Nice fix!

ZStriker19

This looks great! I just have a nitpick/question or two and then should be ready!

ddtrace/contrib/asgi/middleware.py

codecov-commenter · 2022-06-14T21:01:53Z

Codecov Report

Merging #3799 (d754419) into 1.x (5bd3f79) will increase coverage by 0.10%.
The diff coverage is 95.22%.

@@            Coverage Diff             @@
##              1.x    #3799      +/-   ##
==========================================
+ Coverage   78.00%   78.11%   +0.10%     
==========================================
  Files         672      674       +2     
  Lines       51777    52098     +321     
==========================================
+ Hits        40390    40695     +305     
- Misses      11387    11403      +16

Impacted Files	Coverage Δ
ddtrace/contrib/logging/patch.py	`91.17% <0.00%> (-2.77%)`	⬇️
ddtrace/profiling/profiler.py	`0.00% <ø> (ø)`
tests/tracer/telemetry/test_writer.py	`92.53% <ø> (ø)`
ddtrace/_logger.py	`56.25% <56.25%> (ø)`
ddtrace/__init__.py	`100.00% <100.00%> (ø)`
ddtrace/contrib/asgi/middleware.py	`95.37% <100.00%> (+0.13%)`	⬆️
ddtrace/contrib/redis/util.py	`100.00% <100.00%> (ø)`
ddtrace/internal/telemetry/writer.py	`96.26% <100.00%> (+0.08%)`	⬆️
tests/contrib/asgi/test_asgi.py	`100.00% <100.00%> (ø)`
tests/contrib/fastapi/app.py	`93.33% <100.00%> (+0.65%)`	⬆️
... and 5 more

📣 Codecov can now indicate which changes are the most critical in Pull Requests. Learn more

brettlangdon

looks great.

I am worried about a case where we might not finish the request span.

I also think if we can add test cases when more_data is present in the http response body events would be good as well.

ddtrace/contrib/asgi/middleware.py

tests/contrib/asgi/test_asgi.py

…finished with False. Rename tests for clarity.

update with 1.x changes

ZStriker19

Nice tests for more_body ! Looks great!

brettlangdon

minor nit pick over how you are asserting that the span was not finished, but otherwise everything looks great

tests/contrib/asgi/test_asgi.py

Co-authored-by: Brett Langdon <me@brett.is>

wantsui · 2022-06-21T16:37:27Z

@Mergifyio backport 1.2

… web requests (#3799) Following up on #3023, currently libraries traced via the `asgi` integration, such as`fastapi.request` and `starlette.request` spans include the duration of background tasks. This PR updates the asgi middleware code so that spans end earlier by excluding background tasks to better represent the web requests response times. **Current Behavior** $$\begin{align}duration = {http response time} + {background tasks time}\end{align}$$ **What it looks like with the PR** $$\begin{align}duration = {http response time}\end{align}$$ **Example:** An application return a "hello world!" to the user in $2 milliseconds$, but the events that happen in the background lasts another $8 seconds$. With this PR, the span will report a duration of $2 milliseconds$, instead of $2 milliseconds + 8 seconds$. Fixes #3023 Also fixes this failing test: https://app.circleci.com/pipelines/github/DataDog/dd-trace-py/18150/workflows/24caa985-5805-4bff-a4eb-5b143f24a2fb/jobs/1233079 ## Checklist - [ ] Library documentation is updated. - [ ] [Corp site](https://github.com/DataDog/documentation/) documentation is updated (link to the PR). ## Reviewer Checklist - [ ] Title is accurate. - [ ] Description motivates each change. - [ ] No unnecessary changes were introduced in this PR. - [ ] PR cannot be broken up into smaller PRs. - [ ] Avoid breaking [API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces) changes unless absolutely necessary. - [ ] Tests provided or description of manual testing performed is included in the code or PR. - [ ] Release note has been added for fixes and features, or else `changelog/no-changelog` label added. - [ ] All relevant GitHub issues are correctly linked. - [ ] Backports are identified and tagged with Mergifyio. - [ ] Add to milestone. (cherry picked from commit 5b97489)

mergify · 2022-06-21T16:38:06Z

backport 1.2

✅ Backports have been created

#3840 fix(asgi, starlette, fastapi): exclude background task durations from web requests (backport #3799) has been created for branch 1.2

… web requests (backport #3799) (#3840) This is an automatic backport of pull request #3799 done by [Mergify](https://mergify.com). --- <details> <summary>Mergify commands and options</summary> <br /> More conditions and actions can be found in the [documentation](https://docs.mergify.com/). You can also trigger Mergify actions by commenting on this pull request: - `@Mergifyio refresh` will re-evaluate the rules - `@Mergifyio rebase` will rebase this PR on its base branch - `@Mergifyio update` will merge the base branch into this PR - `@Mergifyio backport <destination>` will backport this PR on `<destination>` branch Additionally, on Mergify [dashboard](https://dashboard.mergify.com/) you can: - look at your merge queues - generate the Mergify configuration with the config editor. Finally, you can contact us on https://mergify.com </details>

brettlangdon reviewed Jun 7, 2022

View reviewed changes

ddtrace/contrib/asgi/middleware.py Outdated Show resolved Hide resolved

wantsui changed the title ~~fastapi: exclude background task duration from fastapi request~~ fastapi: exclude background task duration from fastapi and starlette requests Jun 9, 2022

wantsui changed the title ~~fastapi: exclude background task duration from fastapi and starlette requests~~ fastapi: exclude background task durations from fastapi and starlette requests Jun 9, 2022

wantsui marked this pull request as ready for review June 9, 2022 21:21

wantsui requested a review from a team as a code owner June 9, 2022 21:21

wantsui changed the title ~~fastapi: exclude background task durations from fastapi and starlette requests~~ fix(asgi, starlette, fastapi): exclude background task durations from web requests Jun 10, 2022

mergify bot added conflict and removed conflict labels Jun 12, 2022

mabdinur reviewed Jun 13, 2022

View reviewed changes

wantsui force-pushed the wantsui/fastapi-background-duration-update branch from 2bf1234 to 157af78 Compare June 13, 2022 18:49

wantsui added 2 commits June 13, 2022 14:52

Adding background tasks for asgi, starlette, and fastapi. Tests shoul…

e8503b0

…d fail.

Exclude background tasks from web request duration for asgi, starlett…

423ae28

…e, and fastapi. Update the releases for the change.

wantsui force-pushed the wantsui/fastapi-background-duration-update branch from 157af78 to 423ae28 Compare June 13, 2022 21:04

mabdinur previously approved these changes Jun 13, 2022

View reviewed changes

ZStriker19 requested changes Jun 14, 2022

View reviewed changes

ddtrace/contrib/asgi/middleware.py Show resolved Hide resolved

ddtrace/contrib/asgi/middleware.py Outdated Show resolved Hide resolved

Change the more_data comment to more_body.

f5d52d8

wantsui dismissed mabdinur’s stale review via f5d52d8 June 14, 2022 20:25

brettlangdon requested changes Jun 15, 2022

View reviewed changes

ddtrace/contrib/asgi/middleware.py Show resolved Hide resolved

ddtrace/contrib/asgi/middleware.py Show resolved Hide resolved

tests/contrib/asgi/test_asgi.py Show resolved Hide resolved

wantsui added 2 commits June 17, 2022 10:43

Add a test for the condition where more_body: True is returned, then …

0701463

…finished with False. Rename tests for clarity.

Merge branch '1.x' into wantsui/fastapi-background-duration-update

b793238

update with 1.x changes

ZStriker19 previously approved these changes Jun 17, 2022

View reviewed changes

brettlangdon reviewed Jun 18, 2022

View reviewed changes

tests/contrib/asgi/test_asgi.py Outdated Show resolved Hide resolved

tests/contrib/asgi/test_asgi.py Outdated Show resolved Hide resolved

tests/contrib/asgi/test_asgi.py Outdated Show resolved Hide resolved

Merge branch '1.x' into wantsui/fastapi-background-duration-update

d754419

wantsui dismissed ZStriker19’s stale review via 8f4cd65 June 21, 2022 13:14

wantsui and others added 4 commits June 21, 2022 09:14

Update tests/contrib/asgi/test_asgi.py

8f4cd65

Co-authored-by: Brett Langdon <me@brett.is>

Update tests/contrib/asgi/test_asgi.py

3f5c81d

Co-authored-by: Brett Langdon <me@brett.is>

Update tests/contrib/asgi/test_asgi.py

dcd8016

Co-authored-by: Brett Langdon <me@brett.is>

Merge branch '1.x' into wantsui/fastapi-background-duration-update

d09ea75

brettlangdon approved these changes Jun 21, 2022

View reviewed changes

P403n1x87 approved these changes Jun 21, 2022

View reviewed changes

mergify bot merged commit 5b97489 into DataDog:1.x Jun 21, 2022

brettlangdon added this to the v1.3.0 milestone Jun 21, 2022

wantsui deleted the wantsui/fastapi-background-duration-update branch June 21, 2022 16:00

mergify bot mentioned this pull request Jun 21, 2022

fix(asgi, starlette, fastapi): exclude background task durations from web requests (backport #3799) #3840

Merged

marpulli mentioned this pull request Feb 20, 2023

Exclude background tasks from request duration in ASGI middleware open-telemetry/opentelemetry-python-contrib#1684

Closed

emmettbutler mentioned this pull request Jun 12, 2023

Can't get trace or span ID in ASGI style middleware with FastAPI for request log #6030

Closed

siminn-arnorgj mentioned this pull request Sep 14, 2023

Exclude background task execution from root server span in ASGI middleware open-telemetry/opentelemetry-python-contrib#1952

Merged

11 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(asgi, starlette, fastapi): exclude background task durations from web requests #3799

fix(asgi, starlette, fastapi): exclude background task durations from web requests #3799

wantsui commented Jun 7, 2022 •

edited

Loading

mergify bot commented Jun 12, 2022

mabdinur left a comment

ZStriker19 left a comment

codecov-commenter commented Jun 14, 2022 •

edited

Loading

brettlangdon left a comment

ZStriker19 left a comment

brettlangdon left a comment

wantsui commented Jun 21, 2022

mergify bot commented Jun 21, 2022

fix(asgi, starlette, fastapi): exclude background task durations from web requests #3799

fix(asgi, starlette, fastapi): exclude background task durations from web requests #3799

Conversation

wantsui commented Jun 7, 2022 • edited Loading

Checklist

Reviewer Checklist

mergify bot commented Jun 12, 2022

mabdinur left a comment

Choose a reason for hiding this comment

ZStriker19 left a comment

Choose a reason for hiding this comment

codecov-commenter commented Jun 14, 2022 • edited Loading

Codecov Report

brettlangdon left a comment

Choose a reason for hiding this comment

ZStriker19 left a comment

Choose a reason for hiding this comment

brettlangdon left a comment

Choose a reason for hiding this comment

wantsui commented Jun 21, 2022

mergify bot commented Jun 21, 2022

✅ Backports have been created

wantsui commented Jun 7, 2022 •

edited

Loading

codecov-commenter commented Jun 14, 2022 •

edited

Loading