From 3cdf49e6cb08bf4c1a18f229de5da47db12a3d43 Mon Sep 17 00:00:00 2001 From: John DiSanti Date: Wed, 7 Dec 2022 15:06:16 -0800 Subject: [PATCH] Improve client tracing spans (#2044) * Emit spans for implementers of map request middleware traits * Instrument dispatch with its own span * Fix trace span hierarchy * Partially flatten the middleware span hierarchy * Make `MapRequest::name` required * Add sub-spans to the `load_response` span --- CHANGELOG.next.toml | 12 ++++ .../aws-config/src/imds/client/token.rs | 4 ++ .../src/meta/credentials/lazy_caching.rs | 2 +- aws/rust-runtime/aws-endpoint/src/lib.rs | 4 ++ aws/rust-runtime/aws-http/src/auth.rs | 4 ++ .../aws-http/src/recursion_detection.rs | 4 ++ aws/rust-runtime/aws-http/src/user_agent.rs | 4 ++ .../aws-sig-auth/src/middleware.rs | 4 ++ .../rustsdk/AwsFluentClientDecorator.kt | 2 +- .../client/CustomizableOperationGenerator.kt | 2 +- rust-runtime/aws-smithy-client/src/lib.rs | 54 ++++++++++++++-- .../aws-smithy-http-tower/src/dispatch.rs | 5 +- rust-runtime/aws-smithy-http-tower/src/lib.rs | 5 ++ .../aws-smithy-http-tower/src/map_request.rs | 13 ++-- .../src/parse_response.rs | 61 ++++--------------- .../src/endpoint/middleware.rs | 4 ++ .../aws-smithy-http/src/middleware.rs | 42 +++++++++---- 17 files changed, 151 insertions(+), 75 deletions(-) diff --git a/CHANGELOG.next.toml b/CHANGELOG.next.toml index b258fee2ab..19e48e10f9 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 615a52289b..ef3420c88a 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 457d6b9189..2950a0fb7c 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 b09d79c7c9..a4743463df 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 2cb75e08cc..f86a817405 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 5e849598b4..62faa749cd 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 22e7727c42..a9f39dfbf9 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 5847f13155..4feb946dae 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 9841647fdf..0aeddc3ab5 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 74dcb5a3dc..a50e963ecb 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 bee2b0b501..b1e2b1128d 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 77792311b6..5b0d09e1b9 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 4e752b28fb..d2a1c54603 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 87ad0e6a09..5dd72a0c89 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 9d1b4692aa..1f6767c661 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 22467bf826..9f6c8e1a1e 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 311c5ff361..091c7caa71 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> {