Add detailed CRT metrics and tweak per-request logging

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();
 

mountpoint-s3-crt/src/common.rs

@@ -12,6 +12,7 @@ pub mod logging;
 pub mod ref_count;
 pub mod rust_log_adapter;
 pub mod task_scheduler;
+pub mod thread;
 pub mod uri;
 
 static COMMON_LIBRARY_INIT: Once = Once::new();

mountpoint-s3-crt/src/common/thread.rs

@@ -0,0 +1,17 @@
+//! Utilities for managing threads
+
+use mountpoint_s3_crt_sys::aws_thread_id_t;
+
+/// Identifier for a running thread
+///
+/// This is an opaque object that identifies a thread (like [std::thread::ThreadId] but without the
+/// uniqueness guarantee). Its actual value cannot be accessed because the underlying representation
+/// varies across platforms, but it implements [Eq] and [Hash] for comparison purposes.
+#[derive(Debug, Clone, PartialEq, Eq, Hash)]
+pub struct ThreadId(aws_thread_id_t);
+
+impl From<aws_thread_id_t> for ThreadId {
+    fn from(value: aws_thread_id_t) -> Self {
+        Self(value)
+    }
+}