Skip to content

refactor(stack/loadshed): unit test instruments spawned tasks#3755

Merged
cratelyn merged 1 commit intomainfrom
kate/linkerd-stack-loadshed-unit-test-span
Mar 13, 2025
Merged

refactor(stack/loadshed): unit test instruments spawned tasks#3755
cratelyn merged 1 commit intomainfrom
kate/linkerd-stack-loadshed-unit-test-span

Conversation

@cratelyn
Copy link
Member

this commit performs a small refactor to one of the unit tests in linkerd-stack's load-shedding middleware.

this adds a span to the worker tasks spawned in this test, so that tracing logs can be associated with particular oneshot services.

see #3744 for more information on upgrading our tower dependency. this is cherry-picked from investigations on that branch related to breaking changes in 0.5 related to the Buffer middleware.

after this change, logs now look like this:

; RUST_LOG="trace" cargo test -p linkerd-stack buffer_load_shed -- --nocapture

running 1 test
[     0.002770s] TRACE worker{id=oneshot1}: tower::buffer::service: sending request to buffer worker
[     0.002809s] TRACE worker{id=oneshot2}: tower::buffer::service: sending request to buffer worker
[     0.002823s] TRACE worker{id=oneshot3}: tower::buffer::service: sending request to buffer worker
[     0.002843s] DEBUG worker{id=oneshot4}: linkerd_stack::loadshed: Service has become unavailable
[     0.002851s] DEBUG worker{id=oneshot4}: linkerd_stack::loadshed: Service shedding load
[     0.002878s] TRACE tower::buffer::worker: worker polling for next message
[     0.002885s] TRACE tower::buffer::worker: processing new request
[     0.002892s] TRACE worker{id=oneshot1}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.002901s] DEBUG worker{id=oneshot1}: tower::buffer::worker: service.ready=true processing request
[     0.002914s] TRACE worker{id=oneshot1}: tower::buffer::worker: returning response future
[     0.002926s] TRACE tower::buffer::worker: worker polling for next message
[     0.002931s] TRACE tower::buffer::worker: processing new request
[     0.002935s] TRACE worker{id=oneshot2}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.002946s] TRACE worker{id=oneshot2}: tower::buffer::worker: service.ready=false delay
[     0.002983s] TRACE worker{id=oneshot5}: tower::buffer::service: sending request to buffer worker
[     0.003001s] DEBUG worker{id=oneshot6}: linkerd_stack::loadshed: Service has become unavailable
[     0.003007s] DEBUG worker{id=oneshot6}: linkerd_stack::loadshed: Service shedding load
[     0.003017s] DEBUG worker{id=oneshot7}: linkerd_stack::loadshed: Service has become unavailable
[     0.003024s] DEBUG worker{id=oneshot7}: linkerd_stack::loadshed: Service shedding load
[     0.003035s] TRACE tower::buffer::worker: worker polling for next message
[     0.003041s] TRACE tower::buffer::worker: resuming buffered request
[     0.003045s] TRACE worker{id=oneshot2}: tower::buffer::worker: resumed=true worker received request; waiting for service readiness
[     0.003052s] DEBUG worker{id=oneshot2}: tower::buffer::worker: service.ready=true processing request
[     0.003060s] TRACE worker{id=oneshot2}: tower::buffer::worker: returning response future
[     0.003068s] TRACE tower::buffer::worker: worker polling for next message
[     0.003073s] TRACE tower::buffer::worker: processing new request
[     0.003077s] TRACE worker{id=oneshot3}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.003084s] DEBUG worker{id=oneshot3}: tower::buffer::worker: service.ready=true processing request
[     0.003091s] TRACE worker{id=oneshot3}: tower::buffer::worker: returning response future
[     0.003099s] TRACE tower::buffer::worker: worker polling for next message
[     0.003103s] TRACE tower::buffer::worker: processing new request
[     0.003107s] TRACE worker{id=oneshot5}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.003114s] DEBUG worker{id=oneshot5}: tower::buffer::worker: service.ready=true processing request
[     0.003121s] TRACE worker{id=oneshot5}: tower::buffer::worker: returning response future
[     0.003129s] TRACE tower::buffer::worker: worker polling for next message
test loadshed::tests::buffer_load_shed ... ok

this commit performs a small refactor to one of the unit tests in
`linkerd-stack`'s load-shedding middleware.

this adds a span to the worker tasks spawned in this test, so that
tracing logs can be associated with particular oneshot services.

see #3744 for more information on upgrading our tower dependency. this
is cherry-picked from investigations on that branch related to breaking
changes in 0.5 related to the `Buffer` middleware.

after this change, logs now look like this:

```
; RUST_LOG="trace" cargo test -p linkerd-stack buffer_load_shed -- --nocapture

running 1 test
[     0.002770s] TRACE worker{id=oneshot1}: tower::buffer::service: sending request to buffer worker
[     0.002809s] TRACE worker{id=oneshot2}: tower::buffer::service: sending request to buffer worker
[     0.002823s] TRACE worker{id=oneshot3}: tower::buffer::service: sending request to buffer worker
[     0.002843s] DEBUG worker{id=oneshot4}: linkerd_stack::loadshed: Service has become unavailable
[     0.002851s] DEBUG worker{id=oneshot4}: linkerd_stack::loadshed: Service shedding load
[     0.002878s] TRACE tower::buffer::worker: worker polling for next message
[     0.002885s] TRACE tower::buffer::worker: processing new request
[     0.002892s] TRACE worker{id=oneshot1}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.002901s] DEBUG worker{id=oneshot1}: tower::buffer::worker: service.ready=true processing request
[     0.002914s] TRACE worker{id=oneshot1}: tower::buffer::worker: returning response future
[     0.002926s] TRACE tower::buffer::worker: worker polling for next message
[     0.002931s] TRACE tower::buffer::worker: processing new request
[     0.002935s] TRACE worker{id=oneshot2}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.002946s] TRACE worker{id=oneshot2}: tower::buffer::worker: service.ready=false delay
[     0.002983s] TRACE worker{id=oneshot5}: tower::buffer::service: sending request to buffer worker
[     0.003001s] DEBUG worker{id=oneshot6}: linkerd_stack::loadshed: Service has become unavailable
[     0.003007s] DEBUG worker{id=oneshot6}: linkerd_stack::loadshed: Service shedding load
[     0.003017s] DEBUG worker{id=oneshot7}: linkerd_stack::loadshed: Service has become unavailable
[     0.003024s] DEBUG worker{id=oneshot7}: linkerd_stack::loadshed: Service shedding load
[     0.003035s] TRACE tower::buffer::worker: worker polling for next message
[     0.003041s] TRACE tower::buffer::worker: resuming buffered request
[     0.003045s] TRACE worker{id=oneshot2}: tower::buffer::worker: resumed=true worker received request; waiting for service readiness
[     0.003052s] DEBUG worker{id=oneshot2}: tower::buffer::worker: service.ready=true processing request
[     0.003060s] TRACE worker{id=oneshot2}: tower::buffer::worker: returning response future
[     0.003068s] TRACE tower::buffer::worker: worker polling for next message
[     0.003073s] TRACE tower::buffer::worker: processing new request
[     0.003077s] TRACE worker{id=oneshot3}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.003084s] DEBUG worker{id=oneshot3}: tower::buffer::worker: service.ready=true processing request
[     0.003091s] TRACE worker{id=oneshot3}: tower::buffer::worker: returning response future
[     0.003099s] TRACE tower::buffer::worker: worker polling for next message
[     0.003103s] TRACE tower::buffer::worker: processing new request
[     0.003107s] TRACE worker{id=oneshot5}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.003114s] DEBUG worker{id=oneshot5}: tower::buffer::worker: service.ready=true processing request
[     0.003121s] TRACE worker{id=oneshot5}: tower::buffer::worker: returning response future
[     0.003129s] TRACE tower::buffer::worker: worker polling for next message
test loadshed::tests::buffer_load_shed ... ok
```

Signed-off-by: katelyn martin <[email protected]>
@cratelyn cratelyn marked this pull request as ready for review March 13, 2025 17:07
@cratelyn cratelyn requested a review from a team as a code owner March 13, 2025 17:07
@cratelyn cratelyn enabled auto-merge (squash) March 13, 2025 17:07
@cratelyn cratelyn merged commit 11e990e into main Mar 13, 2025
15 checks passed
@cratelyn cratelyn deleted the kate/linkerd-stack-loadshed-unit-test-span branch March 13, 2025 17:26
cratelyn added a commit that referenced this pull request Mar 14, 2025
this commit performs a small refactor to one of the unit tests in
`linkerd-stack`'s load-shedding middleware.

this adds a span to the worker tasks spawned in this test, so that
tracing logs can be associated with particular oneshot services.

see #3744 for more information on upgrading our tower dependency. this
is cherry-picked from investigations on that branch related to breaking
changes in 0.5 related to the `Buffer` middleware.

after this change, logs now look like this:

```
; RUST_LOG="trace" cargo test -p linkerd-stack buffer_load_shed -- --nocapture

running 1 test
[     0.002770s] TRACE worker{id=oneshot1}: tower::buffer::service: sending request to buffer worker
[     0.002809s] TRACE worker{id=oneshot2}: tower::buffer::service: sending request to buffer worker
[     0.002823s] TRACE worker{id=oneshot3}: tower::buffer::service: sending request to buffer worker
[     0.002843s] DEBUG worker{id=oneshot4}: linkerd_stack::loadshed: Service has become unavailable
[     0.002851s] DEBUG worker{id=oneshot4}: linkerd_stack::loadshed: Service shedding load
[     0.002878s] TRACE tower::buffer::worker: worker polling for next message
[     0.002885s] TRACE tower::buffer::worker: processing new request
[     0.002892s] TRACE worker{id=oneshot1}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.002901s] DEBUG worker{id=oneshot1}: tower::buffer::worker: service.ready=true processing request
[     0.002914s] TRACE worker{id=oneshot1}: tower::buffer::worker: returning response future
[     0.002926s] TRACE tower::buffer::worker: worker polling for next message
[     0.002931s] TRACE tower::buffer::worker: processing new request
[     0.002935s] TRACE worker{id=oneshot2}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.002946s] TRACE worker{id=oneshot2}: tower::buffer::worker: service.ready=false delay
[     0.002983s] TRACE worker{id=oneshot5}: tower::buffer::service: sending request to buffer worker
[     0.003001s] DEBUG worker{id=oneshot6}: linkerd_stack::loadshed: Service has become unavailable
[     0.003007s] DEBUG worker{id=oneshot6}: linkerd_stack::loadshed: Service shedding load
[     0.003017s] DEBUG worker{id=oneshot7}: linkerd_stack::loadshed: Service has become unavailable
[     0.003024s] DEBUG worker{id=oneshot7}: linkerd_stack::loadshed: Service shedding load
[     0.003035s] TRACE tower::buffer::worker: worker polling for next message
[     0.003041s] TRACE tower::buffer::worker: resuming buffered request
[     0.003045s] TRACE worker{id=oneshot2}: tower::buffer::worker: resumed=true worker received request; waiting for service readiness
[     0.003052s] DEBUG worker{id=oneshot2}: tower::buffer::worker: service.ready=true processing request
[     0.003060s] TRACE worker{id=oneshot2}: tower::buffer::worker: returning response future
[     0.003068s] TRACE tower::buffer::worker: worker polling for next message
[     0.003073s] TRACE tower::buffer::worker: processing new request
[     0.003077s] TRACE worker{id=oneshot3}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.003084s] DEBUG worker{id=oneshot3}: tower::buffer::worker: service.ready=true processing request
[     0.003091s] TRACE worker{id=oneshot3}: tower::buffer::worker: returning response future
[     0.003099s] TRACE tower::buffer::worker: worker polling for next message
[     0.003103s] TRACE tower::buffer::worker: processing new request
[     0.003107s] TRACE worker{id=oneshot5}: tower::buffer::worker: resumed=false worker received request; waiting for service readiness
[     0.003114s] DEBUG worker{id=oneshot5}: tower::buffer::worker: service.ready=true processing request
[     0.003121s] TRACE worker{id=oneshot5}: tower::buffer::worker: returning response future
[     0.003129s] TRACE tower::buffer::worker: worker polling for next message
test loadshed::tests::buffer_load_shed ... ok
```

Signed-off-by: katelyn martin <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants