Improve credentials tracing (#2062)

* Add `info` event for credentials cache miss
* Remove duplicate credential provider spans
* Touch up some credentials events/spans

Author: jdisanti

CHANGELOG.next.toml

@@ -700,4 +700,10 @@ author = "jdisanti"
 message = "Add more `tracing` events to signing and event streams"
 references = ["smithy-rs#2057", "smithy-rs#371"]
 meta = { "breaking" = false, "tada" = false, "bug" = false, "target" = "client"}
-author = "jdisanti"
+author = "jdisanti"
+
+[[aws-sdk-rust]]
+message = "Log an `info` on credentials cache miss and adjust level of some credential `tracing` spans/events."
+references = ["smithy-rs#2062"]
+meta = { "breaking" = false, "tada" = false, "bug" = false }
+author = "jdisanti"

aws/rust-runtime/aws-config/src/imds/credentials.rs

@@ -152,7 +152,7 @@ impl ImdsCredentialsProvider {
             Err(ImdsError::ErrorResponse(context))
                 if context.response().status().as_u16() == 404 =>
             {
-                tracing::info!(
+                tracing::warn!(
                     "received 404 from IMDS when loading profile information. \
                     Hint: This instance may not have an IAM role associated."
                 );

aws/rust-runtime/aws-config/src/meta/credentials/lazy_caching.rs

@@ -6,11 +6,11 @@
 //! Lazy, caching, credentials provider implementation
 
 use std::sync::Arc;
-use std::time::Duration;
+use std::time::{Duration, Instant};
 
 use aws_smithy_async::future::timeout::Timeout;
 use aws_smithy_async::rt::sleep::AsyncSleep;
-use tracing::{trace_span, Instrument};
+use tracing::{debug, info, info_span, Instrument};
 
 use aws_types::credentials::{future, CredentialsError, ProvideCredentials};
 use aws_types::os_shim_internal::TimeSource;
@@ -77,17 +77,18 @@ impl ProvideCredentials for LazyCachingCredentialsProvider {
         future::ProvideCredentials::new(async move {
             // Attempt to get cached credentials, or clear the cache if they're expired
             if let Some(credentials) = cache.yield_or_clear_if_expired(now).await {
-                tracing::debug!("loaded credentials from cache");
+                debug!("loaded credentials from cache");
                 Ok(credentials)
             } else {
                 // If we didn't get credentials from the cache, then we need to try and load.
                 // There may be other threads also loading simultaneously, but this is OK
                 // since the futures are not eagerly executed, and the cache will only run one
                 // of them.
                 let future = Timeout::new(loader.provide_credentials(), timeout_future);
-                cache
+                let start_time = Instant::now();
+                let result = cache
                     .get_or_load(|| {
-                        let span = trace_span!("lazy_load_credentials");
+                        let span = info_span!("lazy_load_credentials");
                         async move {
                             let credentials = future.await.map_err(|_err| {
                                 CredentialsError::provider_timed_out(load_timeout)
@@ -102,7 +103,12 @@ impl ProvideCredentials for LazyCachingCredentialsProvider {
                         // is opened if the cache decides not to execute it.
                         .instrument(span)
                     })
-                    .await
+                    .await;
+                info!(
+                    "credentials cache miss occurred; retrieved new AWS credentials (took {:?})",
+                    start_time.elapsed()
+                );
+                result
             }
         })
     }

aws/rust-runtime/aws-config/src/profile/credentials.rs

@@ -46,10 +46,7 @@ impl ProvideCredentials for ProfileFileCredentialsProvider {
     where
         Self: 'a,
     {
-        future::ProvideCredentials::new(self.load_credentials().instrument(tracing::debug_span!(
-            "load_credentials",
-            provider = %"Profile"
-        )))
+        future::ProvideCredentials::new(self.load_credentials())
     }
 }
 

aws/rust-runtime/aws-config/src/sts/assume_role.rs

@@ -235,8 +235,6 @@ impl AssumeRoleProviderBuilder {
 
 impl Inner {
     async fn credentials(&self) -> credentials::Result {
-        tracing::info!("assuming role");
-
         tracing::debug!("retrieving assumed credentials");
         let op = self
             .op
@@ -281,7 +279,7 @@ impl ProvideCredentials for Inner {
     {
         future::ProvideCredentials::new(
             self.credentials()
-                .instrument(tracing::info_span!("assume_role")),
+                .instrument(tracing::debug_span!("assume_role")),
         )
     }
 }

aws/rust-runtime/aws-config/src/web_identity_token.rs

@@ -71,7 +71,6 @@ use aws_types::credentials::{self, future, CredentialsError, ProvideCredentials}
 use aws_types::os_shim_internal::{Env, Fs};
 use std::borrow::Cow;
 use std::path::{Path, PathBuf};
-use tracing::Instrument;
 
 const ENV_VAR_TOKEN_FILE: &str = "AWS_WEB_IDENTITY_TOKEN_FILE";
 const ENV_VAR_ROLE_ARN: &str = "AWS_ROLE_ARN";
@@ -161,10 +160,6 @@ impl WebIdentityTokenCredentialsProvider {
             &conf.role_arn,
             &conf.session_name,
         )
-        .instrument(tracing::debug_span!(
-            "load_credentials",
-            provider = "WebIdentityToken"
-        ))
         .await
     }
 }