diff --git a/CHANGELOG.next.toml b/CHANGELOG.next.toml index b258fee2ab09586ce831c22f5d774788a0479b4e..19e48e10f96a0c83282f2bc7cf7bddca4e7ef0a5 100644 --- a/CHANGELOG.next.toml +++ b/CHANGELOG.next.toml @@ -677,3 +677,15 @@ The Unit type for a Union member is no longer rendered. The serializers and pars references = ["smithy-rs#1989"] meta = { "breaking" = true, "tada" = false, "bug" = false, "target" = "all" } author = "ysaito1001" + +[[aws-sdk-rust]] +message = "Fixed and improved the request `tracing` span hierarchy to improve log messages, profiling, and debuggability." +references = ["smithy-rs#2044", "smithy-rs#371"] +meta = { "breaking" = false, "tada" = true, "bug" = false } +author = "jdisanti" + +[[smithy-rs]] +message = "Fixed and improved the request `tracing` span hierarchy to improve log messages, profiling, and debuggability." +references = ["smithy-rs#2044", "smithy-rs#371"] +meta = { "breaking" = false, "tada" = true, "bug" = false, "target" = "client"} +author = "jdisanti" diff --git a/aws/rust-runtime/aws-config/src/imds/client/token.rs b/aws/rust-runtime/aws-config/src/imds/client/token.rs index 615a52289be0c2aa66232d2d405b3d5b079dcf62..ef3420c88aeb189479d3edc9fc2c8c49f57973c2 100644 --- a/aws/rust-runtime/aws-config/src/imds/client/token.rs +++ b/aws/rust-runtime/aws-config/src/imds/client/token.rs @@ -160,6 +160,10 @@ impl AsyncMapRequest for TokenMiddleware { type Error = ImdsError; type Future = Pin> + Send + 'static>>; + fn name(&self) -> &'static str { + "attach_imds_token" + } + fn apply(&self, request: Request) -> Self::Future { let this = self.clone(); Box::pin(async move { this.add_token(request).await }) diff --git a/aws/rust-runtime/aws-config/src/meta/credentials/lazy_caching.rs b/aws/rust-runtime/aws-config/src/meta/credentials/lazy_caching.rs index 457d6b91891cce5305e441263812c69820d3c9bf..2950a0fb7c3632078e02f965cb03a5c4d75f2631 100644 --- a/aws/rust-runtime/aws-config/src/meta/credentials/lazy_caching.rs +++ b/aws/rust-runtime/aws-config/src/meta/credentials/lazy_caching.rs @@ -84,10 +84,10 @@ impl ProvideCredentials for LazyCachingCredentialsProvider { // 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 span = trace_span!("lazy_load_credentials"); let future = Timeout::new(loader.provide_credentials(), timeout_future); cache .get_or_load(|| { + let span = trace_span!("lazy_load_credentials"); async move { let credentials = future.await.map_err(|_err| { CredentialsError::provider_timed_out(load_timeout) diff --git a/aws/rust-runtime/aws-endpoint/src/lib.rs b/aws/rust-runtime/aws-endpoint/src/lib.rs index b09d79c7c98280bad620ee05b2b176eb42621c1c..a4743463dfb800c874d1a9c78ca8aec6347d45e7 100644 --- a/aws/rust-runtime/aws-endpoint/src/lib.rs +++ b/aws/rust-runtime/aws-endpoint/src/lib.rs @@ -133,6 +133,10 @@ impl From for AwsAuthStageError { impl MapRequest for AwsAuthStage { type Error = AwsAuthStageError; + fn name(&self) -> &'static str { + "resolve_endpoint" + } + fn apply(&self, request: Request) -> Result { request.augment(|http_req, props| { let endpoint = props diff --git a/aws/rust-runtime/aws-http/src/auth.rs b/aws/rust-runtime/aws-http/src/auth.rs index 2cb75e08cc1d8edfd3a9eb18e2261cd5e122f83a..f86a8174050650bb07a113ae8bde3a84e9a235a5 100644 --- a/aws/rust-runtime/aws-http/src/auth.rs +++ b/aws/rust-runtime/aws-http/src/auth.rs @@ -101,6 +101,10 @@ impl AsyncMapRequest for CredentialsStage { type Error = CredentialsStageError; type Future = Pin> + Send + 'static>>; + fn name(&self) -> &'static str { + "retrieve_credentials" + } + fn apply(&self, request: Request) -> BoxFuture> { Box::pin(Self::load_creds(request)) } diff --git a/aws/rust-runtime/aws-http/src/recursion_detection.rs b/aws/rust-runtime/aws-http/src/recursion_detection.rs index 5e849598b4fa36b0037ab5a58752c6785efdb90d..62faa749cd37ec3d5bf11e6e0c0fcaf2697547d6 100644 --- a/aws/rust-runtime/aws-http/src/recursion_detection.rs +++ b/aws/rust-runtime/aws-http/src/recursion_detection.rs @@ -33,6 +33,10 @@ impl RecursionDetectionStage { impl MapRequest for RecursionDetectionStage { type Error = std::convert::Infallible; + fn name(&self) -> &'static str { + "recursion_detection" + } + fn apply(&self, request: Request) -> Result { request.augment(|mut req, _conf| { augument_request(&mut req, &self.env); diff --git a/aws/rust-runtime/aws-http/src/user_agent.rs b/aws/rust-runtime/aws-http/src/user_agent.rs index 22e7727c4215ab044aebbe2fe358469d9f447ba3..a9f39dfbf92e072d79bc5fdc953077cdce920421 100644 --- a/aws/rust-runtime/aws-http/src/user_agent.rs +++ b/aws/rust-runtime/aws-http/src/user_agent.rs @@ -582,6 +582,10 @@ lazy_static::lazy_static! { impl MapRequest for UserAgentStage { type Error = UserAgentStageError; + fn name(&self) -> &'static str { + "generate_user_agent" + } + fn apply(&self, request: Request) -> Result { request.augment(|mut req, conf| { let ua = conf diff --git a/aws/rust-runtime/aws-sig-auth/src/middleware.rs b/aws/rust-runtime/aws-sig-auth/src/middleware.rs index 5847f1315502016af07dfc3d900840eed06bb71e..4feb946dae001586606743a8f2bfbfd4016ca7ec 100644 --- a/aws/rust-runtime/aws-sig-auth/src/middleware.rs +++ b/aws/rust-runtime/aws-sig-auth/src/middleware.rs @@ -155,6 +155,10 @@ fn signing_config( impl MapRequest for SigV4SigningStage { type Error = SigningStageError; + fn name(&self) -> &'static str { + "sigv4_sign_request" + } + fn apply(&self, req: Request) -> Result { req.augment(|mut req, config| { let operation_config = config diff --git a/aws/sdk-codegen/src/main/kotlin/software/amazon/smithy/rustsdk/AwsFluentClientDecorator.kt b/aws/sdk-codegen/src/main/kotlin/software/amazon/smithy/rustsdk/AwsFluentClientDecorator.kt index 9841647fdf2260f6b3d7cd52bbde4c7714509935..0aeddc3ab5e8c03015e85882b0f04c022d0833e2 100644 --- a/aws/sdk-codegen/src/main/kotlin/software/amazon/smithy/rustsdk/AwsFluentClientDecorator.kt +++ b/aws/sdk-codegen/src/main/kotlin/software/amazon/smithy/rustsdk/AwsFluentClientDecorator.kt @@ -323,7 +323,7 @@ private fun renderCustomizableOperationSendMethod( /// Sends this operation's request pub async fn send(self) -> Result> where - E: std::error::Error + 'static, + E: std::error::Error + Send + Sync + 'static, O: #{ParseHttpResponse}> + Send + Sync + Clone + 'static, Retry: #{ClassifyRetry}<#{SdkSuccess}, SdkError> + Send + Sync + Clone, { diff --git a/codegen-client/src/main/kotlin/software/amazon/smithy/rust/codegen/client/smithy/generators/client/CustomizableOperationGenerator.kt b/codegen-client/src/main/kotlin/software/amazon/smithy/rust/codegen/client/smithy/generators/client/CustomizableOperationGenerator.kt index 74dcb5a3dc77a17875907e9f06ca6d5e9a2b89bb..a50e963ecbd117b0c7dd83d99f0156a6d6981b27 100644 --- a/codegen-client/src/main/kotlin/software/amazon/smithy/rust/codegen/client/smithy/generators/client/CustomizableOperationGenerator.kt +++ b/codegen-client/src/main/kotlin/software/amazon/smithy/rust/codegen/client/smithy/generators/client/CustomizableOperationGenerator.kt @@ -160,7 +160,7 @@ class CustomizableOperationGenerator( /// Sends this operation's request pub async fn send(self) -> Result> where - E: std::error::Error + 'static, + E: std::error::Error + Send + Sync + 'static, O: #{ParseHttpResponse}> + Send + Sync + Clone + 'static, Retry: Send + Sync + Clone, ::Policy: #{SmithyRetryPolicy} + Clone, diff --git a/rust-runtime/aws-smithy-client/src/lib.rs b/rust-runtime/aws-smithy-client/src/lib.rs index bee2b0b50100a052ae1bdda4a323d833eea0e332..b1e2b1128d6f60b0da86ab53d58680cf1d565671 100644 --- a/rust-runtime/aws-smithy-client/src/lib.rs +++ b/rust-runtime/aws-smithy-client/src/lib.rs @@ -97,12 +97,14 @@ pub use aws_smithy_http::result::{SdkError, SdkSuccess}; use aws_smithy_http::retry::ClassifyRetry; use aws_smithy_http_tower::dispatch::DispatchLayer; use aws_smithy_http_tower::parse_response::ParseResponseLayer; +use aws_smithy_types::error::display::DisplayErrorContext; use aws_smithy_types::retry::ProvideErrorKind; use aws_smithy_types::timeout::OperationTimeoutConfig; use std::error::Error; use std::sync::Arc; use timeout::ClientTimeoutParams; use tower::{Layer, Service, ServiceBuilder, ServiceExt}; +use tracing::{debug_span, field, field::display, Instrument}; /// Smithy service client. /// @@ -173,16 +175,16 @@ where /// /// For ergonomics, this does not include the raw response for successful responses. To /// access the raw response use `call_raw`. - pub async fn call(&self, input: Operation) -> Result> + pub async fn call(&self, op: Operation) -> Result> where O: Send + Sync, - E: 'static, + E: std::error::Error + Send + Sync + 'static, Retry: Send + Sync, R::Policy: bounds::SmithyRetryPolicy, bounds::Parsed<>::Service, O, Retry>: Service, Response = SdkSuccess, Error = SdkError> + Clone, { - self.call_raw(input).await.map(|res| res.parsed) + self.call_raw(op).await.map(|res| res.parsed) } /// Dispatch this request to the network @@ -191,11 +193,11 @@ where /// implementing unsupported features. pub async fn call_raw( &self, - input: Operation, + op: Operation, ) -> Result, SdkError> where O: Send + Sync, - E: 'static, + E: std::error::Error + Send + Sync + 'static, Retry: Send + Sync, R::Policy: bounds::SmithyRetryPolicy, // This bound is not _technically_ inferred by all the previous bounds, but in practice it @@ -226,7 +228,47 @@ where .layer(DispatchLayer::new()) .service(connector); - check_send_sync(svc).ready().await?.call(input).await + // send_operation records the full request-response lifecycle. + // NOTE: For operations that stream output, only the setup is captured in this span. + let span = debug_span!( + "send_operation", + operation = field::Empty, + service = field::Empty, + status = field::Empty, + message = field::Empty + ); + let (mut req, parts) = op.into_request_response(); + if let Some(metadata) = &parts.metadata { + span.record("operation", &metadata.name()); + span.record("service", &metadata.service()); + // This will clone two `Cow::<&'static str>::Borrow`s in the vast majority of cases + req.properties_mut().insert(metadata.clone()); + } + let op = Operation::from_parts(req, parts); + + let result = async move { check_send_sync(svc).ready().await?.call(op).await } + .instrument(span.clone()) + .await; + match &result { + Ok(_) => { + span.record("status", &"ok"); + } + Err(err) => { + span.record( + "status", + &match err { + SdkError::ConstructionFailure(_) => "construction_failure", + SdkError::DispatchFailure(_) => "dispatch_failure", + SdkError::ResponseError(_) => "response_error", + SdkError::ServiceError(_) => "service_error", + SdkError::TimeoutError(_) => "timeout_error", + _ => "error", + }, + ) + .record("message", &display(DisplayErrorContext(err))); + } + } + result } /// Statically check the validity of a `Client` without a request to send. diff --git a/rust-runtime/aws-smithy-http-tower/src/dispatch.rs b/rust-runtime/aws-smithy-http-tower/src/dispatch.rs index 77792311b6a18bf98cbc36adf257c0079a7c6f91..5b0d09e1b9ac95983038d2a1dea15e1c4a2f2e5a 100644 --- a/rust-runtime/aws-smithy-http-tower/src/dispatch.rs +++ b/rust-runtime/aws-smithy-http-tower/src/dispatch.rs @@ -11,7 +11,7 @@ use std::future::Future; use std::pin::Pin; use std::task::{Context, Poll}; use tower::{Layer, Service}; -use tracing::trace; +use tracing::{debug_span, trace, Instrument}; /// Connects Operation driven middleware to an HTTP implementation. /// @@ -50,7 +50,8 @@ where .await .map(|resp| operation::Response::from_parts(resp, property_bag)) .map_err(|e| SendOperationError::RequestDispatchError(e.into())) - }; + } + .instrument(debug_span!("dispatch")); Box::pin(future) } } diff --git a/rust-runtime/aws-smithy-http-tower/src/lib.rs b/rust-runtime/aws-smithy-http-tower/src/lib.rs index 4e752b28fbb03bd355a2543569f0431bad85cb53..d2a1c546033631a0538a0ccaddeffb82977c5b20 100644 --- a/rust-runtime/aws-smithy-http-tower/src/lib.rs +++ b/rust-runtime/aws-smithy-http-tower/src/lib.rs @@ -76,6 +76,11 @@ mod tests { struct AddHeader; impl MapRequest for AddHeader { type Error = Infallible; + + fn name(&self) -> &'static str { + "add_header" + } + fn apply(&self, request: Request) -> Result { request.augment(|mut req, _| { req.headers_mut() diff --git a/rust-runtime/aws-smithy-http-tower/src/map_request.rs b/rust-runtime/aws-smithy-http-tower/src/map_request.rs index 87ad0e6a09d92f678772d4ae1b01d394474fd499..5dd72a0c89d9d1366a4b7b652304b4fbb4f24c34 100644 --- a/rust-runtime/aws-smithy-http-tower/src/map_request.rs +++ b/rust-runtime/aws-smithy-http-tower/src/map_request.rs @@ -11,6 +11,7 @@ use std::future::Future; use std::pin::Pin; use std::task::{Context, Poll}; use tower::{Layer, Service}; +use tracing::{debug_span, Instrument}; #[derive(Debug)] pub struct AsyncMapRequestLayer { @@ -61,10 +62,13 @@ where } fn call(&mut self, req: operation::Request) -> Self::Future { + let mapper_name = self.mapper.name(); let mut inner = self.inner.clone(); let future = self.mapper.apply(req); Box::pin(async move { + let span = debug_span!("async_map_request", name = mapper_name); let mapped_request = future + .instrument(span) .await .map_err(|e| SendOperationError::RequestConstructionError(e.into()))?; inner.call(mapped_request).await @@ -122,8 +126,8 @@ where } } -#[derive(Clone)] /// Tower service for [`MapRequest`](aws_smithy_http::middleware::MapRequest) +#[derive(Clone)] pub struct MapRequestService { inner: S, mapper: M, @@ -143,9 +147,10 @@ where } fn call(&mut self, req: operation::Request) -> Self::Future { - match self - .mapper - .apply(req) + let span = debug_span!("map_request", name = self.mapper.name()); + let mapper = &self.mapper; + match span + .in_scope(|| mapper.apply(req)) .map_err(|e| SendOperationError::RequestConstructionError(e.into())) { Err(e) => MapRequestFuture::Ready { inner: Some(e) }, diff --git a/rust-runtime/aws-smithy-http-tower/src/parse_response.rs b/rust-runtime/aws-smithy-http-tower/src/parse_response.rs index 9d1b4692aa42df04987c2779de93d6381254cc5d..1f6767c661c437286ec4da8100c9446c51fddcf0 100644 --- a/rust-runtime/aws-smithy-http-tower/src/parse_response.rs +++ b/rust-runtime/aws-smithy-http-tower/src/parse_response.rs @@ -8,15 +8,13 @@ use aws_smithy_http::middleware::load_response; use aws_smithy_http::operation; use aws_smithy_http::operation::Operation; use aws_smithy_http::response::ParseHttpResponse; -use aws_smithy_http::result::SdkError; -use aws_smithy_types::error::display::DisplayErrorContext; +use aws_smithy_http::result::{SdkError, SdkSuccess}; use std::future::Future; use std::marker::PhantomData; use std::pin::Pin; use std::task::{Context, Poll}; use tower::{Layer, Service}; -use tracing::field::display; -use tracing::{debug_span, field, Instrument}; +use tracing::{debug_span, Instrument}; /// `ParseResponseService` dispatches [`Operation`](aws_smithy_http::operation::Operation)s and parses them. /// @@ -68,7 +66,7 @@ type BoxedResultFuture = Pin> + Send> /// `E`: The error path return of the response parser /// `R`: The type of the retry policy impl - tower::Service> + Service> for ParseResponseService where InnerService: @@ -80,8 +78,8 @@ where + 'static, FailureResponse: std::error::Error + 'static, { - type Response = aws_smithy_http::result::SdkSuccess; - type Error = aws_smithy_http::result::SdkError; + type Response = SdkSuccess; + type Error = SdkError; type Future = BoxedResultFuture; fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll> { @@ -89,54 +87,19 @@ where } fn call(&mut self, req: Operation) -> Self::Future { - let (mut req, parts) = req.into_request_response(); + let (req, parts) = req.into_request_response(); let handler = parts.response_handler; - // send_operation records the full request-response lifecycle. - // NOTE: For operations that stream output, only the setup is captured in this span. - let span = debug_span!( - "send_operation", - operation = field::Empty, - service = field::Empty, - status = field::Empty, - message = field::Empty - ); - let inner_span = span.clone(); - if let Some(metadata) = parts.metadata { - span.record("operation", &metadata.name()); - span.record("service", &metadata.service()); - req.properties_mut().insert(metadata); - } let resp = self.inner.call(req); - let fut = async move { - let resp = match resp.await { + Box::pin(async move { + match resp.await { Err(e) => Err(e.into()), Ok(resp) => { - // load_response contains reading the body as far as is required & parsing the response - let response_span = debug_span!("load_response"); load_response(resp, &handler) - .instrument(response_span) + // load_response contains reading the body as far as is required & parsing the response + .instrument(debug_span!("load_response")) .await } - }; - match &resp { - Ok(_) => inner_span.record("status", &"ok"), - Err(err) => inner_span - .record( - "status", - &match err { - SdkError::ConstructionFailure(_) => "construction_failure", - SdkError::DispatchFailure(_) => "dispatch_failure", - SdkError::ResponseError(_) => "response_error", - SdkError::ServiceError(_) => "service_error", - SdkError::TimeoutError(_) => "timeout_error", - _ => "error", - }, - ) - .record("message", &display(DisplayErrorContext(err))), - }; - resp - } - .instrument(span); - Box::pin(fut) + } + }) } } diff --git a/rust-runtime/aws-smithy-http/src/endpoint/middleware.rs b/rust-runtime/aws-smithy-http/src/endpoint/middleware.rs index 22467bf826544e4ece6cb0a5e31b6e039544559e..9f6c8e1a1efb5a6b8d8e203409c7a59ae02fb150 100644 --- a/rust-runtime/aws-smithy-http/src/endpoint/middleware.rs +++ b/rust-runtime/aws-smithy-http/src/endpoint/middleware.rs @@ -27,6 +27,10 @@ impl SmithyEndpointStage { impl MapRequest for SmithyEndpointStage { type Error = ResolveEndpointError; + fn name(&self) -> &'static str { + "resolve_endpoint" + } + fn apply(&self, request: Request) -> Result { request.augment(|mut http_req, props| { // we need to do a little dance so that this works with retries. diff --git a/rust-runtime/aws-smithy-http/src/middleware.rs b/rust-runtime/aws-smithy-http/src/middleware.rs index 311c5ff3617b8dcbd09234417732702a30efb110..091c7caa714bd5012e6aeb76ca19c9be21a6ca04 100644 --- a/rust-runtime/aws-smithy-http/src/middleware.rs +++ b/rust-runtime/aws-smithy-http/src/middleware.rs @@ -17,7 +17,7 @@ use http_body::Body; use pin_utils::pin_mut; use std::error::Error; use std::future::Future; -use tracing::trace; +use tracing::{debug_span, trace, Instrument}; type BoxError = Box; @@ -33,6 +33,9 @@ pub trait AsyncMapRequest { type Error: Into + 'static; type Future: Future> + Send + 'static; + /// Returns the name of this map request operation for inclusion in a tracing span. + fn name(&self) -> &'static str; + fn apply(&self, request: operation::Request) -> Self::Future; } @@ -42,16 +45,26 @@ pub trait AsyncMapRequest { /// augment the request. Most fundamental middleware is expressed as `MapRequest`, including /// signing & endpoint resolution. /// +/// ## Examples +/// /// ```rust /// # use aws_smithy_http::middleware::MapRequest; /// # use std::convert::Infallible; /// # use aws_smithy_http::operation; /// use http::header::{HeaderName, HeaderValue}; -/// struct AddHeader(HeaderName, HeaderValue); +/// /// /// Signaling struct added to the request property bag if a header should be added /// struct NeedsHeader; +/// +/// struct AddHeader(HeaderName, HeaderValue); +/// /// impl MapRequest for AddHeader { /// type Error = Infallible; +/// +/// fn name(&self) -> &'static str { +/// "add_header" +/// } +/// /// fn apply(&self, request: operation::Request) -> Result { /// request.augment(|mut request, properties| { /// if properties.get::().is_some() { @@ -68,6 +81,9 @@ pub trait MapRequest { /// If this middleware never fails use [std::convert::Infallible] or similar. type Error: Into; + /// Returns the name of this map request operation for inclusion in a tracing span. + fn name(&self) -> &'static str; + /// Apply this middleware to a request. /// /// Typically, implementations will use [`request.augment`](crate::operation::Request::augment) @@ -90,14 +106,16 @@ pub async fn load_response( where O: ParseHttpResponse>, { - if let Some(parsed_response) = handler.parse_unloaded(&mut response) { - trace!(response = ?response); + if let Some(parsed_response) = + debug_span!("parse_unloaded").in_scope(&mut || handler.parse_unloaded(&mut response)) + { + trace!(response = ?response, "read HTTP headers for streaming response"); return sdk_result(parsed_response, response); } let (http_response, properties) = response.into_parts(); let (parts, body) = http_response.into_parts(); - let body = match read_body(body).await { + let body = match read_body(body).instrument(debug_span!("read_body")).await { Ok(body) => body, Err(err) => { return Err(SdkError::response_error( @@ -111,12 +129,14 @@ where }; let http_response = http::Response::from_parts(parts, Bytes::from(body)); - trace!(http_response = ?http_response); - let parsed = handler.parse_loaded(&http_response); - sdk_result( - parsed, - operation::Response::from_parts(http_response.map(SdkBody::from), properties), - ) + trace!(http_response = ?http_response, "read HTTP response body"); + debug_span!("parse_loaded").in_scope(move || { + let parsed = handler.parse_loaded(&http_response); + sdk_result( + parsed, + operation::Response::from_parts(http_response.map(SdkBody::from), properties), + ) + }) } async fn read_body(body: B) -> Result, B::Error> {