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.

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

Conversation

david-perez
Copy link
Contributor

@david-perez david-perez commented Apr 12, 2022

This commit adds minimal tracing at the DEBUG level to the
code-generated OperationHandler trait implementations for each
operation, logging the deserialized operation input as well as any
errors. The router also has some minimal tracing to detect requests that
are not routed successfully.

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

Examples

Successful pokemon-species operation:

2022-04-12T16:59:06.780701Z DEBUG hyper::proto::h1::io: 205: parsed 3 headers
2022-04-12T16:59:06.780743Z DEBUG hyper::proto::h1::conn: 217: incoming body is empty
2022-04-12T16:59:06.781142Z DEBUG router: aws_smithy_http_server::routing: 157: request routed successfully to operation
2022-04-12T16:59:06.781286Z DEBUG request{method=GET uri=/pokemon-species/pikachu version=HTTP/1.1}: tower_http::trace::on_request: 91: started processing request
2022-04-12T16:59:06.781383Z DEBUG request{method=GET uri=/pokemon-species/pikachu version=HTTP/1.1}: pokemon_service: 139: Requested Pokémon is pikachu
2022-04-12T16:59:06.781549Z DEBUG request{method=GET uri=/pokemon-species/pikachu version=HTTP/1.1}: tower_http::trace::on_response: 254: finished processing request latency=0 ms status=200
2022-04-12T16:59:06.781694Z DEBUG hyper::proto::h1::io: 312: flushed 526 bytes
2022-04-12T16:59:06.781850Z DEBUG hyper::proto::h1::conn: 276: read eof

Unsuccessful pokemon-species operation:

2022-04-12T16:59:52.865557Z DEBUG hyper::proto::h1::io: 205: parsed 3 headers
2022-04-12T16:59:52.865598Z DEBUG hyper::proto::h1::conn: 217: incoming body is empty
2022-04-12T16:59:52.865985Z DEBUG router: aws_smithy_http_server::routing: 157: request routed successfully to operation
2022-04-12T16:59:52.866123Z DEBUG request{method=GET uri=/pokemon-species/magikarp version=HTTP/1.1}: tower_http::trace::on_request: 91: started processing request
2022-04-12T16:59:52.866234Z ERROR request{method=GET uri=/pokemon-species/magikarp version=HTTP/1.1}: pokemon_service: 161: Requested Pokémon `magikarp` not available
2022-04-12T16:59:52.866387Z DEBUG request{method=GET uri=/pokemon-species/magikarp version=HTTP/1.1}: tower_http::trace::on_response: 254: finished processing request latency=0 ms status=404
2022-04-12T16:59:52.866532Z DEBUG hyper::proto::h1::io: 312: flushed 206 bytes
2022-04-12T16:59:52.866658Z DEBUG hyper::proto::h1::conn: 276: read eof

Unsuccessful routing:

2022-04-12T17:00:44.832441Z DEBUG hyper::proto::h1::io: 205: parsed 3 headers
2022-04-12T17:00:44.832487Z DEBUG hyper::proto::h1::conn: 217: incoming body is empty
2022-04-12T17:00:44.832733Z DEBUG router: aws_smithy_http_server::routing: 166: request does not match any operation route method=GET uri=/not-found headers={"host": "localhost:13734", "user-agent": "curl/7.79.1", "accept": "*/*"} version=HTTP/1.1
2022-04-12T17:00:44.832898Z DEBUG hyper::proto::h1::io: 312: flushed 82 bytes
2022-04-12T17:00:44.833046Z DEBUG hyper::proto::h1::conn: 276: read eof

This commit adds minimal tracing at the `DEBUG` level to the
code-generated `OperationHandler` trait implementations for each
operation, logging the deserialized operation input as well as any
errors. The router also has some minimal tracing to detect requests that
are not routed successfully.
@david-perez david-perez requested a review from a team as a code owner April 12, 2022 15:58
@github-actions
Copy link

A new generated diff is ready to view.

A new doc preview is ready to view.

Rust Wrk benchmark report:

Duration: 90 sec, Connections: 32, Threads: 2

Measurement Deviation Current Old
Requests/sec -4.00% 38453.61 40056.79
Total requests -4.05% 3462972 3609061
Total errors NaN% 0 0
Total successes -4.05% 3462972 3609061
Average latency ms 2.35% 0.87 0.85
Minimum latency ms 50.00% 0.03 0.02
Maximum latency ms 17.50% 21.55 18.34
Stdev latency ms -14.71% 0.58 0.68
Transfer Mb -4.05% 359.98 375.16
Connect errors NaN% 0 0
Read errors NaN% 0 0
Write errors NaN% 0 0
Status errors (not 2xx/3xx) NaN% 0 0
Timeout errors NaN% 0 0

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?

@@ -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.

@david-perez
Copy link
Contributor Author

The Pokémon Service should change its usage of TraceLayer to configure it so that the request URI is not logged, since it can contain sensitive data.

@david-perez
Copy link
Contributor Author

Closing in favor of #1536.

@david-perez david-perez closed this Aug 3, 2022
@david-perez david-perez deleted the davidpz-tracing branch August 3, 2022 23:34
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants