Add tracing calls when an extension parameter cannot be constructed (#3378)

## Motivation and Context

When a user defines a handler function with additional parameters, these
parameters are constructed using the `FromRequest` trait implementation
specific to their types. If `FromRequest` fails to construct the
parameter – for instance, if `Extension<State>` is expected by the user
but `Extension<Arc<State>>` is actually added by the extension layer –
the server currently does not log a message indicating this construction
failure. Instead, it simply returns a 500 internal server error.

## Description

`tracing::{trace, error}` calls have been added.

## Breaking change

`FromParts<P>::Rejection` **must** implement `std::fmt::Display`.

----

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

---------

Co-authored-by: Fahad Zubair <fahadzub@amazon.com>

Author: drganjoo

rust-runtime/aws-smithy-http-server/Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "aws-smithy-http-server"
-version = "0.62.1"
+version = "0.63.0"
 authors = ["Smithy Rust Server <smithy-rs-server@amazon.com>"]
 edition = "2021"
 license = "Apache-2.0"

rust-runtime/aws-smithy-http-server/src/operation/upgrade.rs

@@ -117,6 +117,7 @@ pin_project! {
 impl<P, Input, B, S> Future for UpgradeFuture<P, Input, B, S>
 where
     Input: FromRequest<P, B>,
+    <Input as FromRequest<P, B>>::Rejection: std::fmt::Display,
     S: Service<Input>,
     S::Response: IntoResponse<P>,
     S::Error: IntoResponse<P>,
@@ -137,7 +138,13 @@ where
                             .take()
                             .expect("futures cannot be polled after completion")
                             .oneshot(ok),
-                        Err(err) => return Poll::Ready(Ok(err.into_response())),
+                        Err(err) => {
+                            // The error may arise either from a `FromRequest` failure for any user-defined
+                            // handler's additional input parameters, or from a de-serialization failure
+                            // of an input parameter specific to the operation.
+                            tracing::trace!(error = %err, "parameter for the handler cannot be constructed");
+                            return Poll::Ready(Ok(err.into_response()));
+                        }
                     }
                 }
                 InnerProj::Inner { call } => {
@@ -158,6 +165,7 @@ where
 impl<P, Input, B, S> Service<http::Request<B>> for Upgrade<P, Input, S>
 where
     Input: FromRequest<P, B>,
+    <Input as FromRequest<P, B>>::Rejection: std::fmt::Display,
     S: Service<Input> + Clone,
     S::Response: IntoResponse<P>,
     S::Error: IntoResponse<P>,

rust-runtime/aws-smithy-http-server/src/protocol/aws_json/runtime_error.rs

@@ -11,12 +11,22 @@ use http::StatusCode;
 
 use super::rejection::{RequestRejection, ResponseRejection};
 
-#[derive(Debug)]
+#[derive(Debug, thiserror::Error)]
 pub enum RuntimeError {
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::Serialization`]
+    #[error("request failed to deserialize or response failed to serialize: {0}")]
     Serialization(crate::Error),
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::InternalFailure`]
+    #[error("internal failure: {0}")]
     InternalFailure(crate::Error),
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::NotAcceptable`]
+    #[error("not acceptable request: request contains an `Accept` header with a MIME type, and the server cannot return a response body adhering to that MIME type")]
     NotAcceptable,
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::UnsupportedMediaType`]
+    #[error("unsupported media type: request does not contain the expected `Content-Type` header value")]
     UnsupportedMediaType,
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::Validation`]
+    #[error("validation failure: operation input contains data that does not adhere to the modeled constraints: {0}")]
     Validation(String),
 }
 

rust-runtime/aws-smithy-http-server/src/protocol/rest_json_1/runtime_error.rs

@@ -38,23 +38,28 @@ use crate::runtime_error::InternalFailureException;
 use crate::runtime_error::INVALID_HTTP_RESPONSE_FOR_RUNTIME_ERROR_PANIC_MESSAGE;
 use http::StatusCode;
 
-#[derive(Debug)]
+#[derive(Debug, thiserror::Error)]
 pub enum RuntimeError {
     /// Request failed to deserialize or response failed to serialize.
+    #[error("request failed to deserialize or response failed to serialize: {0}")]
     Serialization(crate::Error),
     /// As of writing, this variant can only occur upon failure to extract an
     /// [`crate::extension::Extension`] from the request.
+    #[error("internal failure: {0}")]
     InternalFailure(crate::Error),
-    /// Request contained an `Accept` header with a MIME type, and the server cannot return a response
+    /// Request contains an `Accept` header with a MIME type, and the server cannot return a response
     /// body adhering to that MIME type.
-    /// This is returned directly (i.e. without going through a [`RequestRejection`] first) in the
-    /// generated SDK when calling [`crate::protocol::accept_header_classifier`] in
-    /// `from_request`.
+    // This is returned directly (i.e. without going through a [`RequestRejection`] first) in the
+    // generated SDK when calling [`crate::protocol::accept_header_classifier`] in
+    // `from_request`.
+    #[error("not acceptable request: request contains an `Accept` header with a MIME type, and the server cannot return a response body adhering to that MIME type")]
     NotAcceptable,
     /// The request does not contain the expected `Content-Type` header value.
+    #[error("unsupported media type: request does not contain the expected `Content-Type` header value")]
     UnsupportedMediaType,
     /// Operation input contains data that does not adhere to the modeled [constraint traits].
     /// [constraint traits]: <https://awslabs.github.io/smithy/2.0/spec/constraint-traits.html>
+    #[error("validation failure: operation input contains data that does not adhere to the modeled constraints: {0}")]
     Validation(String),
 }
 

rust-runtime/aws-smithy-http-server/src/protocol/rest_xml/runtime_error.rs

@@ -11,12 +11,22 @@ use http::StatusCode;
 
 use super::rejection::{RequestRejection, ResponseRejection};
 
-#[derive(Debug)]
+#[derive(Debug, thiserror::Error)]
 pub enum RuntimeError {
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::Serialization`]
+    #[error("request failed to deserialize or response failed to serialize: {0}")]
     Serialization(crate::Error),
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::InternalFailure`]
+    #[error("internal failure: {0}")]
     InternalFailure(crate::Error),
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::NotAcceptable`]
+    #[error("not acceptable request: request contains an `Accept` header with a MIME type, and the server cannot return a response body adhering to that MIME type")]
     NotAcceptable,
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::UnsupportedMediaType`]
+    #[error("unsupported media type: request does not contain the expected `Content-Type` header value")]
     UnsupportedMediaType,
+    /// See: [`crate::protocol::rest_json_1::runtime_error::RuntimeError::Validation`]
+    #[error("validation failure: operation input contains data that does not adhere to the modeled constraints: {0}")]
     Validation(String),
 }
 

rust-runtime/aws-smithy-http-server/src/rejection.rs

@@ -25,11 +25,16 @@ pub mod any_rejections {
     //! [`IntoResponse`].
 
     use super::IntoResponse;
+    use thiserror::Error;
 
     macro_rules! any_rejection {
         ($name:ident, $($var:ident),+) => (
+            #[derive(Debug, Error)]
             pub enum $name<$($var),*> {
-                $($var ($var),)*
+                $(
+                    #[error("{0}")]
+                    $var($var),
+                )*
             }
 
             impl<P, $($var,)*> IntoResponse<P> for $name<$($var),*>

rust-runtime/aws-smithy-http-server/src/request/mod.rs

@@ -163,15 +163,34 @@ impl<P, B, T1, T2> FromRequest<P, B> for (T1, T2)
 where
     T1: FromRequest<P, B>,
     T2: FromParts<P>,
+    T1::Rejection: std::fmt::Display,
+    T2::Rejection: std::fmt::Display,
 {
     type Rejection = any_rejections::Two<T1::Rejection, T2::Rejection>;
     type Future = TryJoin<MapErr<T1::Future, fn(T1::Rejection) -> Self::Rejection>, Ready<Result<T2, Self::Rejection>>>;
 
     fn from_request(request: Request<B>) -> Self::Future {
         let (mut parts, body) = request.into_parts();
-        let t2_result = T2::from_parts(&mut parts).map_err(any_rejections::Two::B);
+        let t2_result: Result<T2, any_rejections::Two<T1::Rejection, T2::Rejection>> = T2::from_parts(&mut parts)
+            .map_err(|e| {
+                // The error is likely caused by a failure to construct a parameter from the
+                // `Request` required by the user handler. This typically occurs when the
+                // user handler expects a specific type, such as `Extension<State>`, but
+                // either the `ExtensionLayer` has not been added, or it adds a different
+                // type to the extension bag, such as `Extension<Arc<State>>`.
+                tracing::error!(
+                    error = %e,
+                    "additional parameter for the handler function could not be constructed");
+                any_rejections::Two::B(e)
+            });
         try_join(
-            T1::from_request(Request::from_parts(parts, body)).map_err(any_rejections::Two::A),
+            T1::from_request(Request::from_parts(parts, body)).map_err(|e| {
+                // `T1`, the first parameter of a handler function, represents the input parameter
+                // defined in the Smithy model. An error at this stage suggests that `T1` could not
+                // be constructed from the `Request`.
+                tracing::debug!(error = %e, "failed to deserialize request into operation's input");
+                any_rejections::Two::A(e)
+            }),
             ready(t2_result),
         )
     }