Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add minimal tracing to server framework #1314

Closed
wants to merge 1 commit into from
Closed

Add minimal tracing to server framework #1314

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions ...rc/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/ServerCargoDependency.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ object ServerCargoDependency {
val PinProjectLite: CargoDependency = CargoDependency("pin-project-lite", CratesIo("0.2"))
val SerdeUrlEncoded: CargoDependency = CargoDependency("serde_urlencoded", CratesIo("0.7"))
val Tower: CargoDependency = CargoDependency("tower", CratesIo("0.4"))
val Tracing: CargoDependency = CargoDependency("tracing", CratesIo("0.1"))

fun SmithyHttpServer(runtimeConfig: RuntimeConfig) = runtimeConfig.runtimeCrate("http-server")
}
Expand Down
45 changes: 35 additions & 10 deletions ...re/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationHandlerGenerator.kt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,7 @@ class ServerOperationHandlerGenerator(
"SmithyHttpServer" to ServerCargoDependency.SmithyHttpServer(runtimeConfig).asType(),
"Phantom" to ServerRuntimeType.Phantom,
"ServerOperationHandler" to ServerRuntimeType.serverOperationHandler(runtimeConfig),
"Tracing" to ServerCargoDependency.Tracing.asType(),
"http" to RuntimeType.http,
)

Expand Down Expand Up @@ -78,41 +79,62 @@ class ServerOperationHandlerGenerator(
""".trimIndent(),
*codegenScope
) {
// Instrument operation handler at callsite.
val operationHandlerInvoke = if (state) {
"self(input_inner, state)"
} else {
"self(input_inner)"
}
val operationHandlerCall =
"""
let input_inner = input_wrapper.into();
#{Tracing}::debug!(input = ?input_inner, "calling operation handler");
let output_inner = $operationHandlerInvoke
.instrument(#{Tracing}::debug_span!("${operationName}_handler"))
.await;
#{Tracing}::debug!(output = ?output_inner, "operation handler returned");
"""
val callImpl = if (state) {
"""
let state = match $serverCrate::extension::extract_extension(&mut req).await {
Ok(v) => v,
Err(extension_not_found_rejection) => {
#{Tracing}::error!(?extension_not_found_rejection, "unable to extract extension from request; maybe you forgot to register it with `AddExtensionLayer`?");
let extension = $serverCrate::extension::RuntimeErrorExtension::new(extension_not_found_rejection.to_string());
let runtime_error = $serverCrate::runtime_error::RuntimeError {
protocol: #{SmithyHttpServer}::protocols::Protocol::${protocol.name.toPascalCase()},
kind: extension_not_found_rejection.into(),
};
let mut response = runtime_error.into_response();
response.extensions_mut().insert(extension);
return response.map($serverCrate::body::boxed);
let response = response.map($serverCrate::body::boxed);
#{Tracing}::debug!(?response, "returning HTTP response");
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Response bodies should probably only be logged at TRACE level, since they can be very big.

Same for request bodies, which I'm not logging anywhere.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Most boxed types don't have a real debug impl https://docs.rs/http-body/latest/src/http_body/combinators/box_body.rs.html#32-36 so is this actually useful to print the body?

return response;
}
};
let input_inner = input_wrapper.into();
let output_inner = self(input_inner, state).await;
""".trimIndent()
} else {
$operationHandlerCall
"""
let input_inner = input_wrapper.into();
let output_inner = self(input_inner).await;
""".trimIndent()
} else {
operationHandlerCall
}
rustTemplate(
"""
type Sealed = #{ServerOperationHandler}::sealed::Hidden;

##[#{Tracing}::instrument(level = "debug", skip_all, name = "${operationName}_service_call")]
async fn call(self, req: #{http}::Request<B>) -> #{http}::Response<#{SmithyHttpServer}::body::BoxBody> {
use #{Tracing}::Instrument;

let mut req = #{AxumCore}::extract::RequestParts::new(req);
use #{AxumCore}::extract::FromRequest;
use #{AxumCore}::response::IntoResponse;
let input_wrapper = match $inputWrapperName::from_request(&mut req).await {
Ok(v) => v,
Err(runtime_error) => {
return runtime_error.into_response().map($serverCrate::body::boxed);
#{Tracing}::debug!(?runtime_error, "unable to extract operation input from request");
let response = runtime_error.into_response().map($serverCrate::body::boxed);
#{Tracing}::debug!(?response, "returning HTTP response");
return response;
}
};
$callImpl
Expand All @@ -121,7 +143,9 @@ class ServerOperationHandlerGenerator(
response.extensions_mut().insert(
#{SmithyHttpServer}::extension::OperationExtension::new("${operation.id.namespace}", "$operationName")
);
response.map(#{SmithyHttpServer}::body::boxed)
response = response.map(#{SmithyHttpServer}::body::boxed);
#{Tracing}::debug!(?response, "returning HTTP response");
response
}
""",
*codegenScope
Expand Down Expand Up @@ -157,6 +181,7 @@ class ServerOperationHandlerGenerator(
Fut: std::future::Future<Output = $outputType> + Send,
B: $serverCrate::body::HttpBody + Send + 'static, $streamingBodyTraitBounds
B::Data: Send,
B: std::fmt::Debug,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't really like adding debug bounds like this since sometimes it can be painful. I think we should avoid maybe logging bodies?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unless its an error then I would try to convert the body into a string to print that maybe?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking of logging them at TRACE level, but they can contain sensitive data (https://awslabs.github.io/smithy/1.0/spec/core/documentation-traits.html#sensitive-trait), so it's best that we don't log anything by default. Perhaps we can do it in a separate Tower middleware users can opt into if they absolutely must log bodies.

$serverCrate::rejection::RequestRejection: From<<B as $serverCrate::body::HttpBody>::Error>
""".trimIndent()
}
Expand Down
1 change: 1 addition & 0 deletions rust-runtime/aws-smithy-http-server/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,7 @@ thiserror = "1"
tokio = { version = "1.0", features = ["full"] }
tower = { version = "0.4.11", features = ["util", "make"], default-features = false }
tower-http = { version = "0.2.1", features = ["add-extension", "map-response-body"] }
tracing = "0.1"

[dev-dependencies]
pretty_assertions = "1"
Expand Down
2 changes: 1 addition & 1 deletion rust-runtime/aws-smithy-http-server/examples/Makefile
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@ build: codegen
cargo build

run: codegen
cargo run
RUST_LOG=DEBUG cargo run

doc-open: codegen
cargo doc --no-deps --open
Expand Down
4 changes: 3 additions & 1 deletion rust-runtime/aws-smithy-http-server/examples/pokemon_service/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -124,6 +124,8 @@ impl Default for State {
}
}

// Operation handler implementations get automatically instrumented at the callsite within a new
// `tracing::span::Span`.
/// Retrieves information about a Pokémon species.
pub async fn get_pokemon_species(
input: input::GetPokemonSpeciesInput,
Expand Down Expand Up @@ -156,7 +158,7 @@ pub async fn get_pokemon_species(
Ok(output)
}
None => {
tracing::error!("Requested Pokémon {} not available", input.name);
tracing::error!("Requested Pokémon `{}` not available", input.name);
Err(error::GetPokemonSpeciesError::ResourceNotFoundException(
error::ResourceNotFoundException {
message: String::from("Requested Pokémon not available"),
Expand Down
9 changes: 9 additions & 0 deletions rust-runtime/aws-smithy-http-server/src/routing/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -146,13 +146,15 @@ where
Poll::Ready(Ok(()))
}

#[tracing::instrument(level = "debug", skip_all, name = "router")]
#[inline]
fn call(&mut self, req: Request<B>) -> Self::Future {
let mut method_not_allowed = false;

for (route, request_spec) in &self.routes {
match request_spec.matches(&req) {
request_spec::Match::Yes => {
tracing::debug!("request routed successfully to operation");
return RouterFuture::from_oneshot(route.clone().oneshot(req));
}
request_spec::Match::MethodNotAllowed => method_not_allowed = true,
Expand All @@ -161,6 +163,13 @@ where
}
}

tracing::debug!(
method = ?req.method(),
uri = ?req.uri(),
headers = ?req.headers(),
version = ?req.version(),
"request does not match any operation route"
);
let status_code = if method_not_allowed {
StatusCode::METHOD_NOT_ALLOWED
} else {
Expand Down