Unverified Commit bdbb1b24 authored by Russell Cohen's avatar Russell Cohen Committed by GitHub
Browse files

Improve logging for the credentials cache (#3428) 

## Motivation and Context
Make it easier to understand why credentials are expired. New log
example:

```
2024-02-19T17:47:31.769924Z  INFO lazy_load_identity: aws_smithy_runtime::client::identity::cache::lazy: identity cache miss occurred; added new identity (took 861.893ms) new_expiration=2024-02-19T18:47:31Z valid_for=3599.230108s partition=IdentityCachePartition(1)
```

----

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

rust-runtime/aws-smithy-runtime/src/client/identity/cache/lazy.rs

+8 −2
Original line number Diff line number Diff line
@@ -15,6 +15,7 @@ use aws_smithy_runtime_api::client::identity::{ 
use aws_smithy_runtime_api::client::runtime_components::RuntimeComponents;

use aws_smithy_runtime_api::shared::IntoShared;

use aws_smithy_types::config_bag::ConfigBag;

use aws_smithy_types::DateTime;

use std::collections::HashMap;

use std::fmt;

use std::sync::RwLock;
@@ -303,7 +304,8 @@ impl ResolveCachedIdentity for LazyCache { 
        let now = time_source.now();

        let timeout_future = sleep_impl.sleep(self.load_timeout);

        let load_timeout = self.load_timeout;

        let cache = self.partitions.partition(resolver.cache_partition());

        let partition = resolver.cache_partition();

        let cache = self.partitions.partition(partition);

        let default_expiration = self.default_expiration;



        IdentityFuture::new(async move {
@@ -351,9 +353,13 @@ impl ResolveCachedIdentity for LazyCache { 
                            // `cache.get_or_load` above. In the case of multiple threads concurrently executing

                            // `cache.get_or_load`, logging inside `cache.get_or_load` ensures that it is emitted

                            // only once for the first thread that succeeds in populating a cache value.

                            let printable = DateTime::from(expiration);

                            tracing::info!(

                                new_expiration=%printable,

                                valid_for=?expiration.duration_since(time_source.now()).unwrap_or_default(),

                                partition=?partition,

                                "identity cache miss occurred; added new identity (took {:?})",

                                time_source.now().duration_since(start_time)

                                time_source.now().duration_since(start_time).unwrap_or_default()

                            );



                            Ok((identity, expiration + jitter))

rust-runtime/aws-smithy-runtime/src/expiring_cache.rs

+2 −0
Original line number Diff line number Diff line
@@ -80,6 +80,8 @@ where 
        if let Some((value, expiry)) = self.value.read().await.get() {

            if !expired(*expiry, self.buffer_time, now) {

                return Some(value.clone());

            } else {

                tracing::debug!(expiry = ?expiry, delta= ?now.duration_since(*expiry), "An item existed but it expired.")

            }

        }