Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

excessive logging during credential load #872

Closed
mattklein123 opened this issue Aug 17, 2023 · 6 comments
Closed

excessive logging during credential load #872

mattklein123 opened this issue Aug 17, 2023 · 6 comments
Labels
bug This issue is a bug. p1 This is a high priority issue

Comments

@mattklein123
Copy link

Describe the bug

With recent SDK versions I'm seeing:

[08-17-23 15:16:41.746Z 8 INFO tracing::span] lazy_load_credentials;
[08-17-23 15:16:41.746Z 8 INFO tracing::span] try_op;
[08-17-23 15:16:41.746Z 8 INFO tracing::span] try_attempt;
[08-17-23 15:16:41.849Z 8 INFO tracing::span] finally_attempt;
[08-17-23 15:16:41.849Z 8 INFO tracing::span] finally_op;

Every time a credential is loaded.

I can manually squelch tracing::span but am worried I might miss something else. Can these logs be dropped to debug or trace? Or is there a better way to squelch? Thank you.

Expected Behavior

Logs as debug/trace level

Current Behavior

Per above.

Reproduction Steps

Use the default credential provider and load credentials.

Possible Solution

No response

Additional Information/Context

No response

Version

0.29

Environment details (OS name and version, etc.)

MacOs/Linux

Logs

No response
@mattklein123 mattklein123 added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Aug 17, 2023
@jdisanti jdisanti added p1 This is a high priority issue and removed needs-triage This issue or PR still needs to be triaged. labels Aug 17, 2023
@jdisanti
Copy link
Contributor

Thanks for reporting this!

@rcoh
Copy link
Contributor

rcoh commented Aug 18, 2023

It would probably be handy to add a "logging volume regression test" — we can use the existing sensitive logging tests but instead track the total volume when run on INFO to catch future regressions.

ysaito1001 added a commit to smithy-lang/smithy-rs that referenced this issue Aug 18, 2023
@ysaito1001
Reduce the amount of logging from instrument
8d5abe6 
This commit addresses awslabs/aws-sdk-rust#872
by specifying the log level `TRACE` wherever we use `instrument` in the
file.
@ysaito1001 ysaito1001 mentioned this issue Aug 18, 2023
Open
ysaito1001 added a commit to smithy-lang/smithy-rs that referenced this issue Aug 18, 2023
@ysaito1001
Reduce the amount of logging from instrument
2bb8026 
This commit addresses awslabs/aws-sdk-rust#872
by specifying the log level `TRACE` wherever we use `instrument` in the
file.
@ysaito1001 ysaito1001 mentioned this issue Aug 18, 2023
Merged
2 tasks
jdisanti pushed a commit to smithy-lang/smithy-rs that referenced this issue Aug 18, 2023
@ysaito1001
Reduce amount of logging from #[instrument] (#2934)
c742b5f 
**Will be merged to `smithy-rs-release-0.56.x` branch**

Addresses awslabs/aws-sdk-rust#872

## Motivation and Context
With the introduction of the orchestrator, the core functions that live
in `aws-smithy-runtime/src/client/orchestrator.rs` were annotated by
`#instrument`. By default this emits logs at the `INFO` level, which
caused our customer to see the excessive amount of logging after
switching to the latest SDK creates `0.29`.

## Description
This PR reduces the log level to `DEBUG` wherever we use `#instrument`
throughout the file.

## Testing
No new tests have been added as part of this PR. [An
enhancement](#2932) has been
filed to check logging volume.

Here is a quick check that all instances in the file specify `trace`:
```
✗ rg "instrument"
src/client/orchestrator.rs
34:use tracing::{debug, debug_span, instrument, trace, Instrument};
160:    .instrument(debug_span!("invoke", service = %service_name, operation = %operation_name))
167:#[instrument(skip_all, level = "debug")]
186:#[instrument(skip_all, level = "debug")]
319:#[instrument(skip_all, level = "debug")]
389:                .instrument(debug_span!("read_body"))
398:    .instrument(debug_span!("deserialization"))
407:#[instrument(skip_all, level = "debug")]
419:#[instrument(skip_all, level = "debug")]
```

## Checklist
<!--- If a checkbox below is not applicable, then please DELETE it
rather than leaving it unchecked -->
- [x] I have updated `CHANGELOG.next.toml` if I made changes to the
smithy-rs codegen or runtime crates
- [x] I have updated `CHANGELOG.next.toml` if I made changes to the AWS
SDK, generated SDK code, or SDK runtime crates

----

_By submitting this pull request, I confirm that you can use, modify,
copy, and redistribute this contribution, under the terms of your
choice._

---------

Co-authored-by: ysaito1001 <[email protected]>
@jdisanti jdisanti added the pending-release This issue will be fixed by an approved PR that hasn't been released yet. label Aug 18, 2023
@jdisanti
Copy link
Contributor

A fix for this will go out in the next release.

@mattklein123
Copy link
Author

Wow thank you for the fast turnaround!

@jdisanti
Copy link
Contributor

This has been fixed with the August 23rd release.

@github-actions
Copy link

⚠️COMMENT VISIBILITY WARNING⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.

@rcoh rcoh removed the pending-release This issue will be fixed by an approved PR that hasn't been released yet. label Nov 7, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug This issue is a bug. p1 This is a high priority issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jdisanti @rcoh @mattklein123