Add detailed CRT metrics and tweak per-request logging

This change is a few related things to make logging more useful:
- Include verbose CRT request metrics at trace level. We emit what we
  think is the "interesting" stuff at higher levels, but for detailed
  investigation we might want to see the raw CRT view.
- Add parameters to request spans. This ensures that we know _which_
  request is going wrong when we see log messages about requests.
- Don't log the bucket redirection at warning level, since that's going
  to syslog by default

Signed-off-by: James Bornholt <bornholt@amazon.com>

mountpoint-s3-client/src/s3_crt_client.rs

@@ -38,10 +38,13 @@ use crate::s3_crt_client::get_object::S3GetObjectRequest;
 use crate::s3_crt_client::put_object::S3PutObjectRequest;
 
 macro_rules! request_span {
-    ($self:expr, $method:expr) => {{
+    ($self:expr, $method:expr, $($field:tt)*) => {{
         let counter = $self.next_request_counter();
-        tracing::debug_span!($method, id = counter)
+        let span = tracing::debug_span!($method, id = counter, $($field)*);
+        span.in_scope(|| tracing::debug!("new request"));
+        span
     }};
+    ($self:expr, $method:expr) => { request_span!($self, $method,) };
 }
 
 pub(crate) mod delete_object;
@@ -399,6 +402,7 @@ impl S3CrtClientInner {
                     "request finished"
                 };
                 event!(log_level, %request_type, http_status, ?range, ?duration, ?ttfb, %request_id, "{}", message);
+                trace!(detailed_metrics=?metrics, "request completed");
 
                 let op = span_telemetry.metadata().map(|m| m.name()).unwrap_or("unknown");
                 if let Some(ttfb) = ttfb {

mountpoint-s3-client/src/s3_crt_client/delete_object.rs

@@ -2,7 +2,6 @@ use std::ops::Deref;
 use std::os::unix::prelude::OsStrExt;
 
 use mountpoint_s3_crt::s3::client::{MetaRequestResult, MetaRequestType};
-use tracing::debug;
 
 use crate::object_client::{DeleteObjectError, DeleteObjectResult, ObjectClientError};
 use crate::{ObjectClientResult, S3CrtClient, S3RequestError};
@@ -14,8 +13,7 @@ impl S3CrtClient {
         bucket: &str,
         key: &str,
     ) -> ObjectClientResult<DeleteObjectResult, DeleteObjectError, S3RequestError> {
-        let span = request_span!(self.inner, "delete_object");
-        span.in_scope(|| debug!(?bucket, ?key, "new request"));
+        let span = request_span!(self.inner, "delete_object", bucket, key);
 
         // Scope the endpoint, message, etc. since otherwise rustc thinks we use Message across the await.
         let request = {

mountpoint-s3-client/src/s3_crt_client/get_object.rs

@@ -11,7 +11,6 @@ use mountpoint_s3_crt::common::error::Error;
 use mountpoint_s3_crt::http::request_response::Header;
 use mountpoint_s3_crt::s3::client::{MetaRequestResult, MetaRequestType};
 use pin_project::pin_project;
-use tracing::debug;
 
 use crate::object_client::{GetBodyPart, GetObjectError, ObjectClientError};
 use crate::s3_crt_client::S3HttpRequest;
@@ -28,10 +27,7 @@ impl S3CrtClient {
         range: Option<Range<u64>>,
         if_match: Option<ETag>,
     ) -> Result<S3GetObjectRequest, ObjectClientError<GetObjectError, S3RequestError>> {
-        let span = request_span!(self.inner, "get_object");
-        span.in_scope(
-            || debug!(?bucket, ?key, ?range, ?if_match, size=?range.as_ref().map(|range| range.end - range.start), "new request"),
-        );
+        let span = request_span!(self.inner, "get_object", bucket, key, ?range, ?if_match);
 
         let mut message = self
             .inner

mountpoint-s3-client/src/s3_crt_client/get_object_attributes.rs

@@ -7,7 +7,6 @@ use mountpoint_s3_crt::{
     s3::client::{MetaRequestResult, MetaRequestType},
 };
 use thiserror::Error;
-use tracing::debug;
 
 use crate::{
     Checksum, GetObjectAttributesError, GetObjectAttributesParts, GetObjectAttributesResult, ObjectAttribute,
@@ -140,17 +139,15 @@ impl S3CrtClient {
                 .add_header(&Header::new("x-amz-object-attributes", object_attributes.join(",")))
                 .map_err(S3RequestError::construction_failure)?;
 
-            let span = request_span!(self.inner, "get_object_attributes");
-            span.in_scope(|| {
-                debug!(
-                    ?bucket,
-                    ?key,
-                    ?max_parts,
-                    ?part_number_marker,
-                    ?object_attributes,
-                    "new request"
-                )
-            });
+            let span = request_span!(
+                self.inner,
+                "get_object_attributes",
+                bucket,
+                key,
+                ?max_parts,
+                ?part_number_marker,
+                ?object_attributes
+            );
 
             self.inner
                 .make_simple_http_request(message, MetaRequestType::Default, span, |result| {

mountpoint-s3-client/src/s3_crt_client/head_bucket.rs

@@ -2,7 +2,6 @@ use crate::object_client::{ObjectClientError, ObjectClientResult};
 use crate::{S3CrtClient, S3RequestError};
 use mountpoint_s3_crt::s3::client::{MetaRequestResult, MetaRequestType};
 use thiserror::Error;
-use tracing::debug;
 
 #[derive(Error, Debug)]
 #[non_exhaustive]
@@ -29,8 +28,7 @@ impl S3CrtClient {
                 .set_request_path("/")
                 .map_err(S3RequestError::construction_failure)?;
 
-            let span = request_span!(self.inner, "head_bucket");
-            span.in_scope(|| debug!(?bucket, endpoint = ?self.inner.endpoint, "new request"));
+            let span = request_span!(self.inner, "head_bucket", bucket, endpoint=?self.inner.endpoint);
 
             self.inner
                 .make_simple_http_request(message, MetaRequestType::Default, span, |request_result| {

mountpoint-s3-client/src/s3_crt_client/head_object.rs

@@ -7,7 +7,7 @@ use mountpoint_s3_crt::s3::client::{MetaRequestResult, MetaRequestType};
 use thiserror::Error;
 use time::format_description::well_known::Rfc2822;
 use time::OffsetDateTime;
-use tracing::{debug, error};
+use tracing::error;
 
 use crate::object_client::{HeadObjectError, HeadObjectResult, ObjectClientError, ObjectClientResult, ObjectInfo};
 use crate::s3_crt_client::S3RequestError;
@@ -81,8 +81,7 @@ impl S3CrtClient {
             let header: Arc<Mutex<Option<Result<HeadObjectResult, ParseError>>>> = Default::default();
             let header1 = header.clone();
 
-            let span = request_span!(self.inner, "head_object");
-            span.in_scope(|| debug!(?bucket, ?key, "new request"));
+            let span = request_span!(self.inner, "head_object", bucket, key);
 
             self.inner.make_meta_request(
                 message,

mountpoint-s3-client/src/s3_crt_client/list_objects.rs

@@ -6,7 +6,7 @@ use mountpoint_s3_crt::s3::client::{MetaRequestResult, MetaRequestType};
 use thiserror::Error;
 use time::format_description::well_known::Rfc3339;
 use time::OffsetDateTime;
-use tracing::{debug, error};
+use tracing::error;
 
 use crate::object_client::{ListObjectsError, ListObjectsResult, ObjectClientError, ObjectClientResult, ObjectInfo};
 use crate::s3_crt_client::S3RequestError;
@@ -159,17 +159,15 @@ impl S3CrtClient {
                 .set_request_path_and_query("/", query)
                 .map_err(S3RequestError::construction_failure)?;
 
-            let span = request_span!(self.inner, "list_objects");
-            span.in_scope(|| {
-                debug!(
-                    ?bucket,
-                    continued = continuation_token.is_some(),
-                    ?delimiter,
-                    ?max_keys,
-                    ?prefix,
-                    "new request"
-                )
-            });
+            let span = request_span!(
+                self.inner,
+                "list_objects",
+                bucket,
+                continued = continuation_token.is_some(),
+                delimiter,
+                max_keys,
+                prefix
+            );
 
             self.inner
                 .make_simple_http_request(message, MetaRequestType::Default, span, |result| {

mountpoint-s3-client/src/s3_crt_client/put_object.rs

@@ -5,7 +5,7 @@ use crate::{ObjectClientError, PutObjectRequest, PutObjectResult, S3CrtClient, S
 use async_trait::async_trait;
 use mountpoint_s3_crt::io::async_stream::{self, AsyncStreamWriter};
 use mountpoint_s3_crt::s3::client::{ChecksumConfig, MetaRequestType, UploadReview};
-use tracing::{debug, error};
+use tracing::error;
 
 use super::{S3CrtClientInner, S3HttpRequest};
 
@@ -16,8 +16,7 @@ impl S3CrtClient {
         key: &str,
         params: &PutObjectParams,
     ) -> ObjectClientResult<S3PutObjectRequest, PutObjectError, S3RequestError> {
-        let span = request_span!(self.inner, "put_object");
-        span.in_scope(|| debug!(?bucket, ?key, ?params, "create request"));
+        let span = request_span!(self.inner, "put_object", bucket, key);
         let mut message = self
             .inner
             .new_request_template("PUT", bucket)
@@ -36,8 +35,6 @@ impl S3CrtClient {
         let (body_async_stream, writer) = async_stream::new_stream(&self.inner.allocator);
         message.set_body_stream(Some(body_async_stream));
 
-        span.in_scope(|| debug!(?bucket, ?key, ?params, "make request"));
-
         let review_callback = ReviewCallbackBox::default();
         let callback = review_callback.clone();