diff --git a/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGenerator.kt b/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGenerator.kt index 2da280f83d..5dace38b85 100644 --- a/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGenerator.kt +++ b/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGenerator.kt @@ -41,9 +41,9 @@ class StatusCodeSensitivity(private val sensitive: Boolean, runtimeConfig: Runti /** Returns the type of the `MakeFmt`. */ fun type(): Writable = writable { if (sensitive) { - rustTemplate("#{SmithyHttpServer}::logging::MakeSensitive", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::MakeSensitive", *codegenScope) } else { - rustTemplate("#{SmithyHttpServer}::logging::MakeIdentity", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::MakeIdentity", *codegenScope) } } @@ -86,9 +86,9 @@ class LabelSensitivity(internal val labelIndexes: List, internal val greedy /** Returns the type of the `MakeFmt`. */ fun type(): Writable = if (hasRedactions()) writable { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::uri::MakeLabel bool>", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::uri::MakeLabel bool>", *codegenScope) } else writable { - rustTemplate("#{SmithyHttpServer}::logging::MakeIdentity", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::MakeIdentity", *codegenScope) } /** Returns the value of the `GreedyLabel`. */ @@ -96,7 +96,7 @@ class LabelSensitivity(internal val labelIndexes: List, internal val greedy if (greedyLabel != null) { rustTemplate( """ - Some(#{SmithyHttpServer}::logging::sensitivity::uri::GreedyLabel::new(${greedyLabel.segmentIndex}, ${greedyLabel.endOffset}))""", + Some(#{SmithyHttpServer}::instrumentation::sensitivity::uri::GreedyLabel::new(${greedyLabel.segmentIndex}, ${greedyLabel.endOffset}))""", *codegenScope, ) } else { @@ -148,9 +148,9 @@ sealed class HeaderSensitivity( /** Returns the type of the `MakeDebug`. */ fun type(): Writable = writable { if (hasRedactions()) { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::headers::MakeHeaders #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker>", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::headers::MakeHeaders #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker>", *codegenScope) } else { - rustTemplate("#{SmithyHttpServer}::logging::MakeIdentity", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::MakeIdentity", *codegenScope) } } @@ -194,7 +194,7 @@ sealed class HeaderSensitivity( let name_match = #{NameMatch:W}; #{SuffixAndValue:W} - #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { key_suffix, value } + #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { key_suffix, value } } } as fn(&_) -> _ """, @@ -240,9 +240,9 @@ sealed class QuerySensitivity( /** Returns the type of the `MakeFmt`. */ fun type(): Writable = writable { if (hasRedactions()) { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::uri::MakeQuery #{SmithyHttpServer}::logging::sensitivity::uri::QueryMarker>", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::uri::MakeQuery #{SmithyHttpServer}::instrumentation::sensitivity::uri::QueryMarker>", *codegenScope) } else { - rustTemplate("#{SmithyHttpServer}::logging::MakeIdentity", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::MakeIdentity", *codegenScope) } } @@ -267,7 +267,7 @@ sealed class QuerySensitivity( |name: &str| { let key = $allKeysSensitive; let value = #{Value:W}; - #{SmithyHttpServer}::logging::sensitivity::uri::QueryMarker { key, value } + #{SmithyHttpServer}::instrumentation::sensitivity::uri::QueryMarker { key, value } } } as fn(&_) -> _ """, @@ -296,7 +296,7 @@ data class MakeFmt( * parts of the request/response HTTP as sensitive. * * These closures are provided to `RequestFmt` and `ResponseFmt` constructors, which in turn are provided to - * `InstrumentedOperation` to configure logging. These structures can be found in `aws_smithy_http_server::logging`. + * `InstrumentedOperation` to configure logging. These structures can be found in `aws_smithy_http_server::instrumentation`. * * See [Logging in the Presence of Sensitive Data](https://github.com/awslabs/smithy-rs/blob/main/design/src/rfcs/rfc0018_logging_sensitive.md) * for more details. @@ -458,10 +458,10 @@ class ServerHttpSensitivityGenerator( private fun defaultRequestFmt(): MakeFmt { val type = writable { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::DefaultRequestFmt", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::DefaultRequestFmt", *codegenScope) } val value = writable { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::RequestFmt::new()", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::RequestFmt::new()", *codegenScope) } return MakeFmt(type, value) } @@ -483,9 +483,9 @@ class ServerHttpSensitivityGenerator( val type = writable { rustTemplate( """ - #{SmithyHttpServer}::logging::sensitivity::RequestFmt< + #{SmithyHttpServer}::instrumentation::sensitivity::RequestFmt< #{HeaderType:W}, - #{SmithyHttpServer}::logging::sensitivity::uri::MakeUri< + #{SmithyHttpServer}::instrumentation::sensitivity::uri::MakeUri< #{LabelType:W}, #{QueryType:W} > @@ -498,18 +498,18 @@ class ServerHttpSensitivityGenerator( ) } - val value = writable { rustTemplate("#{SmithyHttpServer}::logging::sensitivity::RequestFmt::new()", *codegenScope) } + headerSensitivity.setter() + labelSensitivity.setter() + querySensitivity.setters() + val value = writable { rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::RequestFmt::new()", *codegenScope) } + headerSensitivity.setter() + labelSensitivity.setter() + querySensitivity.setters() return MakeFmt(type, value) } private fun defaultResponseFmt(): MakeFmt { val type = writable { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::DefaultResponseFmt", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::DefaultResponseFmt", *codegenScope) } val value = writable { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::ResponseFmt::new()", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::ResponseFmt::new()", *codegenScope) } return MakeFmt(type, value) } @@ -527,7 +527,7 @@ class ServerHttpSensitivityGenerator( val type = writable { rustTemplate( - "#{SmithyHttpServer}::logging::sensitivity::ResponseFmt<#{HeaderType:W}, #{StatusType:W}>", + "#{SmithyHttpServer}::instrumentation::sensitivity::ResponseFmt<#{HeaderType:W}, #{StatusType:W}>", "HeaderType" to headerSensitivity.type(), "StatusType" to statusCodeSensitivity.type(), *codegenScope, @@ -535,7 +535,7 @@ class ServerHttpSensitivityGenerator( } val value = writable { - rustTemplate("#{SmithyHttpServer}::logging::sensitivity::ResponseFmt::new()", *codegenScope) + rustTemplate("#{SmithyHttpServer}::instrumentation::sensitivity::ResponseFmt::new()", *codegenScope) } + headerSensitivity.setter() + statusCodeSensitivity.setter() return MakeFmt(type, value) diff --git a/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationGenerator.kt b/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationGenerator.kt index 4381642357..b61b1baa45 100644 --- a/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationGenerator.kt +++ b/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationGenerator.kt @@ -61,7 +61,7 @@ class ServerOperationGenerator( type Error = #{Error:W}; } - impl #{SmithyHttpServer}::logging::sensitivity::Sensitivity for $operationName { + impl #{SmithyHttpServer}::instrumentation::sensitivity::Sensitivity for $operationName { type RequestFmt = #{RequestType:W}; type ResponseFmt = #{ResponseType:W}; diff --git a/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationRegistryGenerator.kt b/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationRegistryGenerator.kt index aa549b455d..1952c0f934 100644 --- a/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationRegistryGenerator.kt +++ b/codegen-server/src/main/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerOperationRegistryGenerator.kt @@ -338,7 +338,7 @@ ${operationImplementationStubs(operations)} let svc = #{ServerOperationHandler}::operation(registry.$operationName); let request_fmt = #{RequestFmt:W}; let response_fmt = #{ResponseFmt:W}; - let svc = #{SmithyHttpServer}::logging::InstrumentOperation::new(svc, "$operationName").request_fmt(request_fmt).response_fmt(response_fmt); + let svc = #{SmithyHttpServer}::instrumentation::InstrumentOperation::new(svc, "$operationName").request_fmt(request_fmt).response_fmt(response_fmt); (#{Tower}::util::BoxCloneService::new(svc), $requestSpecVarName) """, "RequestFmt" to sensitivityGen.requestFmt().value, diff --git a/codegen-server/src/test/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGeneratorTest.kt b/codegen-server/src/test/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGeneratorTest.kt index 1b3575a5fb..aba8b71da3 100644 --- a/codegen-server/src/test/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGeneratorTest.kt +++ b/codegen-server/src/test/kotlin/software/amazon/smithy/rust/codegen/server/smithy/generators/ServerHttpSensitivityGeneratorTest.kt @@ -63,8 +63,8 @@ class ServerHttpSensitivityGeneratorTest { rustTemplate( """ let closure = #{Closure:W}; - assert_eq!(closure("query_a"), #{SmithyHttpServer}::logging::sensitivity::uri::QueryMarker { key: false, value: false }); - assert_eq!(closure("query_b"), #{SmithyHttpServer}::logging::sensitivity::uri::QueryMarker { key: false, value: true }); + assert_eq!(closure("query_a"), #{SmithyHttpServer}::instrumentation::sensitivity::uri::QueryMarker { key: false, value: false }); + assert_eq!(closure("query_b"), #{SmithyHttpServer}::instrumentation::sensitivity::uri::QueryMarker { key: false, value: true }); """, "Closure" to querySensitivity.closure(), *codegenScope, @@ -110,7 +110,7 @@ class ServerHttpSensitivityGeneratorTest { rustTemplate( """ let closure = #{Closure:W}; - assert_eq!(closure("wildcard"), #{SmithyHttpServer}::logging::sensitivity::uri::QueryMarker { key: true, value: true }); + assert_eq!(closure("wildcard"), #{SmithyHttpServer}::instrumentation::sensitivity::uri::QueryMarker { key: true, value: true }); """, "Closure" to querySensitivity.closure(), *codegenScope, @@ -158,7 +158,7 @@ class ServerHttpSensitivityGeneratorTest { rustTemplate( """ let closure = #{Closure:W}; - assert_eq!(closure("wildcard"), #{SmithyHttpServer}::logging::sensitivity::uri::QueryMarker { key: true, value: false }); + assert_eq!(closure("wildcard"), #{SmithyHttpServer}::instrumentation::sensitivity::uri::QueryMarker { key: true, value: false }); """, "Closure" to querySensitivity.closure(), *codegenScope, @@ -206,7 +206,7 @@ class ServerHttpSensitivityGeneratorTest { rustTemplate( """ let closure = #{Closure:W}; - assert_eq!(closure("wildcard"), #{SmithyHttpServer}::logging::sensitivity::uri::QueryMarker { key: false, value: true }); + assert_eq!(closure("wildcard"), #{SmithyHttpServer}::instrumentation::sensitivity::uri::QueryMarker { key: false, value: true }); """, "Closure" to querySensitivity.closure(), *codegenScope, @@ -284,9 +284,9 @@ class ServerHttpSensitivityGeneratorTest { """ let closure = #{Closure:W}; let name = #{Http}::header::HeaderName::from_static("header-a"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); let name = #{Http}::header::HeaderName::from_static("header-b"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: true, key_suffix: None }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: true, key_suffix: None }); """, "Closure" to headerData.closure(), *codegenScope, @@ -332,11 +332,11 @@ class ServerHttpSensitivityGeneratorTest { """ let closure = #{Closure:W}; let name = #{Http}::header::HeaderName::from_static("prefix-a"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: true, key_suffix: Some(7) }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: true, key_suffix: Some(7) }); let name = #{Http}::header::HeaderName::from_static("prefix-b"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: true, key_suffix: Some(7) }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: true, key_suffix: Some(7) }); let name = #{Http}::header::HeaderName::from_static("other"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); """, "Closure" to headerData.closure(), *codegenScope, @@ -415,11 +415,11 @@ class ServerHttpSensitivityGeneratorTest { """ let closure = #{Closure:W}; let name = #{Http}::header::HeaderName::from_static("prefix-a"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: false, key_suffix: Some(7) }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: false, key_suffix: Some(7) }); let name = #{Http}::header::HeaderName::from_static("prefix-b"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: false, key_suffix: Some(7) }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: false, key_suffix: Some(7) }); let name = #{Http}::header::HeaderName::from_static("other"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); """, "Closure" to headerData.closure(), *codegenScope, @@ -469,11 +469,11 @@ class ServerHttpSensitivityGeneratorTest { """ let closure = #{Closure:W}; let name = #{Http}::header::HeaderName::from_static("prefix-a"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: true, key_suffix: None }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: true, key_suffix: None }); let name = #{Http}::header::HeaderName::from_static("prefix-b"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: true, key_suffix: None }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: true, key_suffix: None }); let name = #{Http}::header::HeaderName::from_static("other"); - assert_eq!(closure(&name), #{SmithyHttpServer}::logging::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); + assert_eq!(closure(&name), #{SmithyHttpServer}::instrumentation::sensitivity::headers::HeaderMarker { value: false, key_suffix: None }); """, "Closure" to headerData.closure(), *codegenScope, diff --git a/design/src/docs/instrumentation.md b/design/src/docs/instrumentation.md new file mode 100644 index 0000000000..b4647831f5 --- /dev/null +++ b/design/src/docs/instrumentation.md @@ -0,0 +1,119 @@ +# Instrumentation + +A Smithy Rust server uses the [`tracing`](https://github.com/tokio-rs/tracing) crate to provide instrumentation. The customer is responsible for setting up a [`Subscriber`](https://docs.rs/tracing/latest/tracing/subscriber/trait.Subscriber.html) in order to ingest and process [events](https://docs.rs/tracing/latest/tracing/struct.Event.html) - Smithy Rust makes no prescription on the choice of `Subscriber`. Common choices might include: + +- [`tracing_subscriber::fmt`](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/index.html) for printing to `stdout`. +- [`tracing-log`](https://crates.io/crates/tracing-log) to providing compatibility with the [`log`](https://crates.io/crates/log). + +Events are emitted and [spans](https://docs.rs/tracing/latest/tracing/struct.Span.html) are opened by the `aws-smithy-http-server`, `aws-smithy-http-server-python`, and generated crate. The [default](https://docs.rs/tracing/latest/tracing/struct.Metadata.html) [target](https://docs.rs/tracing/latest/tracing/struct.Metadata.html#method.target) is always used + +> The tracing macros default to using the module path where the span or event originated as the target, but it may be overridden. + +and therefore spans and events be filtered using the [`EnvFilter`](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html) and/or [`Targets`](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/targets/struct.Targets.html) filters with crate and module paths. + +For example, + +```bash +RUST_LOG=aws_smithy_http_server=warn,aws_smithy_http_server_python=error +``` + +and + +```rust +let filter = filter::Targets::new().with_target("aws_smithy_http_server", Level::DEBUG); +``` + +In general, Smithy Rust is conservative when using high-priority log levels: + +- ERROR + - Fatal errors, resulting in the termination of the service. + - Requires immediate remediation. +- WARN + - Non-fatal errors, resulting in incomplete operation. + - Indicates service misconfiguration, transient errors, or future changes in behavior. + - Requires inspection and remediation. +- INFO + - Informative events, which occur inside normal operating limits. + - Used for large state transitions, e.g. startup/shutdown. +- DEBUG + - Informative and sparse events, which occur inside normal operating limits. + - Used to debug coarse-grained progress of service. +- TRACE + - Informative and frequent events, which occur inside normal operating limits. + - Used to debug fine-grained progress of service. + +## Spans over the Request/Response lifecycle + +Smithy Rust is built on top of [`tower`](https://github.com/tower-rs/tower), which means that middleware can be used to encompass different periods of the lifecycle of the request and response and identify them with a span. + +An open-source example of such a middleware is [`TraceLayer`](https://docs.rs/tower-http/latest/tower_http/trace/struct.TraceLayer.html) provided by the [`tower-http`](https://docs.rs/tower-http/latest/tower_http/) crate. + +Smithy provides an out-the-box middleware which: + +- Opens a DEBUG level span, prior to request handling, including the operation name and request URI and headers. +- Emits a DEBUG level event, after to request handling, including the response headers and status code. + +This is applied by default and can be enabled and disabled by filtering on `aws_smithy_http_server::logging`. + + + + + +### Example + +The Pokémon service example, located at `rust-runtime/aws-smithy-http-server/examples/pokemon-service`, sets up a `tracing` `Subscriber` as follows: + +```rust +/// Setup `tracing::subscriber` to read the log level from RUST_LOG environment variable. +pub fn setup_tracing() { + let format = tracing_subscriber::fmt::layer().pretty(); + let filter = EnvFilter::try_from_default_env() + .or_else(|_| EnvFilter::try_new("info")) + .unwrap(); + tracing_subscriber::registry().with(format).with(filter).init(); +} +``` + +Running the Pokémon service example using + +```bash +RUST_LOG=aws_smithy_http_server=debug,pokemon_service=debug cargo r +``` + +and then using `cargo t` to run integration tests against the server, yields the following logs: + +```text + 2022-09-27T09:13:35.372517Z DEBUG aws_smithy_http_server::logging::service: response, headers: {"content-type": "application/json", "content-length": "17"}, status_code: 200 OK + at /smithy-rs/rust-runtime/aws-smithy-http-server/src/logging/service.rs:47 + in aws_smithy_http_server::logging::service::request with operation: get_server_statistics, method: GET, uri: /stats, headers: {"host": "localhost:13734"} + + 2022-09-27T09:13:35.374104Z DEBUG pokemon_service: attempting to authenticate storage user + at pokemon-service/src/lib.rs:184 + in aws_smithy_http_server::logging::service::request with operation: get_storage, method: GET, uri: /pokedex/{redacted}, headers: {"passcode": "{redacted}", "host": "localhost:13734"} + + 2022-09-27T09:13:35.374152Z DEBUG pokemon_service: authentication failed + at pokemon-service/src/lib.rs:188 + in aws_smithy_http_server::logging::service::request with operation: get_storage, method: GET, uri: /pokedex/{redacted}, headers: {"passcode": "{redacted}", "host": "localhost:13734"} + + 2022-09-27T09:13:35.374230Z DEBUG aws_smithy_http_server::logging::service: response, headers: {"content-type": "application/json", "x-amzn-errortype": "NotAuthorized", "content-length": "2"}, status_code: 401 Unauthorized + at /smithy-rs/rust-runtime/aws-smithy-http-server/src/logging/service.rs:47 + in aws_smithy_http_server::logging::service::request with operation: get_storage, method: GET, uri: /pokedex/{redacted}, headers: {"passcode": "{redacted}", "host": "localhost:13734"} +``` + +## Interactions with Sensitivity + +Instrumentation interacts with Smithy's [sensitive trait](https://awslabs.github.io/smithy/2.0/spec/documentation-traits.html#sensitive-trait). + +> Sensitive data MUST NOT be exposed in things like exception messages or log output. Application of this trait SHOULD NOT affect wire logging (i.e., logging of all data transmitted to and from servers or clients). + +For this reason, Smithy runtime will never use `tracing` to emit events or open spans that include any sensitive data. This means that the customer can ingest all logs from `aws-smithy-http-server` and `aws-smithy-http-server-*` without fear of violating the sensitive trait. + +The Smithy runtime will not, and cannot, prevent the customer violating the sensitive trait within the operation handlers and custom middleware. It is the responsibility of the customer to not violate the sensitive contract of their own model, care must be taken. + +Smithy shapes can be sensitive while being coupled to the HTTP request/responses via the [HTTP binding traits](https://awslabs.github.io/smithy/2.0/spec/http-bindings.html). This poses a risk when ingesting events which naively capture request/response information. The instrumentation middleware provided by Smithy Rust respects the sensitive trait and will replace sensitive data in its span and event with `{redacted}`. This feature can be seen in the [Example](#example) above. For debugging purposes these redactions can be prevented using the `aws-smithy-http-server` feature flag, `unredacted-logging`. + +Some examples of inadvertently leaking sensitive information: + +- Ingesting tracing events and spans from third-party crates which do not respect sensitivity. + - An concrete example of this would be enabling events from `hyper` or `tokio`. +- Applying middleware which ingests events including HTTP payloads or any other part of the HTTP request/response which can be bound. diff --git a/design/src/rfcs/rfc0018_logging_sensitive.md b/design/src/rfcs/rfc0018_logging_sensitive.md index a38c067cc4..4ae6a27dd3 100644 --- a/design/src/rfcs/rfc0018_logging_sensitive.md +++ b/design/src/rfcs/rfc0018_logging_sensitive.md @@ -395,7 +395,12 @@ Code generation would be need to be used in order to produce the filtering crite ## Changes Checklist - [x] Implement and integrate code generated logging middleware. - - https://github.com/awslabs/smithy-rs/pull/1550 -- [ ] Add logging to `Router` implementation. -- [ ] Write developer guideline. -- [ ] Refactor `Router` to allow for better positioning described in [Middleware Position](#middleware-position). + - +- [x] Add logging to `Router` implementation. + - +- [x] Write developer guideline. + - +- [x] Refactor `Router` to allow for better positioning described in [Middleware Position](#middleware-position). + - + - + - diff --git a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/bin/pokemon-service-tls.rs b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/bin/pokemon-service-tls.rs index d52824b290..1e86a6a0d6 100644 --- a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/bin/pokemon-service-tls.rs +++ b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/bin/pokemon-service-tls.rs @@ -40,8 +40,6 @@ use tokio_rustls::{ rustls::{Certificate, PrivateKey, ServerConfig}, TlsAcceptor, }; -use tower::ServiceBuilder; -use tower_http::trace::TraceLayer; #[derive(Parser, Debug)] #[clap(author, version, about, long_about = None)] @@ -82,11 +80,7 @@ pub async fn main() { // Setup shared state and middlewares. let shared_state = Arc::new(State::default()); - let app = app.layer( - ServiceBuilder::new() - .layer(TraceLayer::new_for_http()) - .layer(AddExtensionLayer::new(shared_state)), - ); + let app = app.layer(AddExtensionLayer::new(shared_state)); let addr: SocketAddr = format!("{}:{}", args.address, args.port) .parse() diff --git a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lambda.rs b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lambda.rs index dd863b5a27..17537ebab1 100644 --- a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lambda.rs +++ b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lambda.rs @@ -12,8 +12,6 @@ use pokemon_service::{ State, }; use pokemon_service_server_sdk::operation_registry::OperationRegistryBuilder; -use tower::ServiceBuilder; -use tower_http::trace::TraceLayer; #[tokio::main] pub async fn main() { @@ -37,11 +35,7 @@ pub async fn main() { // Setup shared state and middlewares. let shared_state = Arc::new(State::default()); - let app = app.layer( - ServiceBuilder::new() - .layer(TraceLayer::new_for_http()) - .layer(AddExtensionLayer::new(shared_state)), - ); + let app = app.layer(AddExtensionLayer::new(shared_state)); let handler = LambdaHandler::new(app); let lambda = lambda_http::run(handler); diff --git a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lib.rs b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lib.rs index 473c257125..93213f73bf 100644 --- a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lib.rs +++ b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/lib.rs @@ -33,10 +33,7 @@ const PIKACHU_JAPANESE_FLAVOR_TEXT: &str = /// Setup `tracing::subscriber` to read the log level from RUST_LOG environment variable. pub fn setup_tracing() { - let format = tracing_subscriber::fmt::layer() - .with_ansi(true) - .with_line_number(true) - .with_level(true); + let format = tracing_subscriber::fmt::layer().pretty(); let filter = EnvFilter::try_from_default_env() .or_else(|_| EnvFilter::try_new("info")) .unwrap(); @@ -184,8 +181,11 @@ pub async fn get_storage( input: input::GetStorageInput, _state: Extension>, ) -> Result { + tracing::debug!("attempting to authenticate storage user"); + // We currently only support Ash and he has nothing stored if !(input.user == "ash" && input.passcode == "pikachu123") { + tracing::debug!("authentication failed"); return Err(error::GetStorageError::NotAuthorized(error::NotAuthorized {})); } Ok(output::GetStorageOutput { collection: vec![] }) diff --git a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/main.rs b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/main.rs index 2bae7c68f6..4122a49d6d 100644 --- a/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/main.rs +++ b/rust-runtime/aws-smithy-http-server/examples/pokemon-service/src/main.rs @@ -13,8 +13,6 @@ use pokemon_service::{ State, }; use pokemon_service_server_sdk::operation_registry::OperationRegistryBuilder; -use tower::ServiceBuilder; -use tower_http::trace::TraceLayer; #[derive(Parser, Debug)] #[clap(author, version, about, long_about = None)] @@ -49,11 +47,7 @@ pub async fn main() { // Setup shared state and middlewares. let shared_state = Arc::new(State::default()); - let app = app.layer( - ServiceBuilder::new() - .layer(TraceLayer::new_for_http()) - .layer(AddExtensionLayer::new(shared_state)), - ); + let app = app.layer(AddExtensionLayer::new(shared_state)); // Start the [`hyper::Server`]. let bind: SocketAddr = format!("{}:{}", args.address, args.port) diff --git a/rust-runtime/aws-smithy-http-server/src/logging/layer.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/layer.rs similarity index 100% rename from rust-runtime/aws-smithy-http-server/src/logging/layer.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/layer.rs diff --git a/rust-runtime/aws-smithy-http-server/src/logging/mod.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/mod.rs similarity index 97% rename from rust-runtime/aws-smithy-http-server/src/logging/mod.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/mod.rs index 99f6f94869..8a809bae8c 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/mod.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/mod.rs @@ -12,7 +12,7 @@ //! //! ``` //! # use std::convert::Infallible; -//! # use aws_smithy_http_server::logging::{*, sensitivity::{*, headers::*, uri::*}}; +//! # use aws_smithy_http_server::instrumentation::{*, sensitivity::{*, headers::*, uri::*}}; //! # use http::{Request, Response}; //! # use tower::{util::service_fn, Service}; //! # async fn service(request: Request<()>) -> Result, Infallible> { diff --git a/rust-runtime/aws-smithy-http-server/src/logging/plugin.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/plugin.rs similarity index 100% rename from rust-runtime/aws-smithy-http-server/src/logging/plugin.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/plugin.rs diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/headers.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/headers.rs similarity index 98% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/headers.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/headers.rs index b76da7c1e1..57e65eb419 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/headers.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/headers.rs @@ -9,7 +9,7 @@ use std::fmt::{Debug, Display, Error, Formatter}; use http::{header::HeaderName, HeaderMap}; -use crate::logging::MakeFmt; +use crate::instrumentation::MakeFmt; use super::Sensitive; @@ -31,7 +31,7 @@ pub struct HeaderMarker { /// # Example /// /// ``` -/// # use aws_smithy_http_server::logging::sensitivity::headers::{SensitiveHeaders, HeaderMarker}; +/// # use aws_smithy_http_server::instrumentation::sensitivity::headers::{SensitiveHeaders, HeaderMarker}; /// # use http::header::HeaderMap; /// # let headers = HeaderMap::new(); /// // Headers with keys equal to "header-name" are sensitive diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/mod.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/mod.rs similarity index 100% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/mod.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/mod.rs diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/request.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/request.rs similarity index 98% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/request.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/request.rs index f2d3321b97..87dfdcb849 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/request.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/request.rs @@ -9,7 +9,7 @@ use std::fmt::{Debug, Error, Formatter}; use http::{header::HeaderName, HeaderMap}; -use crate::logging::{MakeFmt, MakeIdentity}; +use crate::instrumentation::{MakeFmt, MakeIdentity}; use super::{ headers::{HeaderMarker, MakeHeaders}, diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/response.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/response.rs similarity index 98% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/response.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/response.rs index ebc90955a9..6d2212ab09 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/response.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/response.rs @@ -9,7 +9,7 @@ use std::fmt::{Debug, Error, Formatter}; use http::{header::HeaderName, HeaderMap}; -use crate::logging::{MakeFmt, MakeIdentity}; +use crate::instrumentation::{MakeFmt, MakeIdentity}; use super::{ headers::{HeaderMarker, MakeHeaders}, diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/sensitive.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/sensitive.rs similarity index 95% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/sensitive.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/sensitive.rs index df48dbd353..f61da00a02 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/sensitive.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/sensitive.rs @@ -7,7 +7,7 @@ use std::fmt::{Debug, Display, Error, Formatter}; -use crate::logging::MakeFmt; +use crate::instrumentation::MakeFmt; use super::REDACTED; @@ -22,7 +22,7 @@ use super::REDACTED; /// # Example /// /// ``` -/// # use aws_smithy_http_server::logging::sensitivity::Sensitive; +/// # use aws_smithy_http_server::instrumentation::sensitivity::Sensitive; /// # let address = ""; /// tracing::debug!( /// name = %Sensitive("Alice"), diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/label.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/label.rs similarity index 97% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/label.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/label.rs index d96c348abe..ca42a558ed 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/label.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/label.rs @@ -7,7 +7,7 @@ use std::fmt::{Debug, Display, Error, Formatter}; -use crate::logging::{sensitivity::Sensitive, MakeFmt}; +use crate::instrumentation::{sensitivity::Sensitive, MakeFmt}; /// A wrapper around a path [`&str`](str) which modifies the behavior of [`Display`]. Specific path segments are marked /// as sensitive by providing predicate over the segment index. This accommodates the [httpLabel trait] with @@ -18,7 +18,7 @@ use crate::logging::{sensitivity::Sensitive, MakeFmt}; /// # Example /// /// ``` -/// # use aws_smithy_http_server::logging::sensitivity::uri::Label; +/// # use aws_smithy_http_server::instrumentation::sensitivity::uri::Label; /// # use http::Uri; /// # let path = ""; /// // Path segment 2 is redacted and a trailing greedy label @@ -42,7 +42,7 @@ pub struct Label<'a, F> { /// The pattern, `/alpha/beta/{greedy+}/trail`, has segment index 2 and offset from the end of 6. /// /// ```rust -/// # use aws_smithy_http_server::logging::sensitivity::uri::GreedyLabel; +/// # use aws_smithy_http_server::instrumentation::sensitivity::uri::GreedyLabel; /// let greedy_label = GreedyLabel::new(2, 6); /// ``` #[derive(Clone, Debug)] @@ -177,7 +177,7 @@ where mod tests { use http::Uri; - use crate::logging::sensitivity::uri::{tests::EXAMPLES, GreedyLabel}; + use crate::instrumentation::sensitivity::uri::{tests::EXAMPLES, GreedyLabel}; use super::Label; diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/mod.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/mod.rs similarity index 99% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/mod.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/mod.rs index 8438b1492a..5b63d5303a 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/mod.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/mod.rs @@ -15,7 +15,7 @@ use http::Uri; pub use label::*; pub use query::*; -use crate::logging::{MakeDisplay, MakeFmt, MakeIdentity}; +use crate::instrumentation::{MakeDisplay, MakeFmt, MakeIdentity}; /// A wrapper around [`&Uri`](Uri) which modifies the behavior of [`Display`]. Specific parts of the [`Uri`] as are /// marked as sensitive using the methods provided. diff --git a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/query.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/query.rs similarity index 96% rename from rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/query.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/query.rs index 6c25fb1236..34491c3ad1 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/sensitivity/uri/query.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/sensitivity/uri/query.rs @@ -7,7 +7,7 @@ use std::fmt::{Debug, Display, Error, Formatter}; -use crate::logging::{sensitivity::Sensitive, MakeFmt}; +use crate::instrumentation::{sensitivity::Sensitive, MakeFmt}; /// Marks the sensitive data of a query string pair. #[derive(Debug, Default, PartialEq, Eq)] @@ -27,7 +27,7 @@ pub struct QueryMarker { /// # Example /// /// ``` -/// # use aws_smithy_http_server::logging::sensitivity::uri::{Query, QueryMarker}; +/// # use aws_smithy_http_server::instrumentation::sensitivity::uri::{Query, QueryMarker}; /// # let uri = ""; /// // Query string value with key "name" is redacted /// let uri = Query::new(&uri, |x| QueryMarker { key: false, value: x == "name" } ); @@ -119,7 +119,7 @@ where mod tests { use http::Uri; - use crate::logging::sensitivity::uri::tests::{ + use crate::instrumentation::sensitivity::uri::tests::{ ALL_KEYS_QUERY_STRING_EXAMPLES, ALL_PAIRS_QUERY_STRING_EXAMPLES, ALL_VALUES_QUERY_STRING_EXAMPLES, EXAMPLES, QUERY_STRING_EXAMPLES, X_QUERY_STRING_EXAMPLES, }; diff --git a/rust-runtime/aws-smithy-http-server/src/logging/service.rs b/rust-runtime/aws-smithy-http-server/src/instrumentation/service.rs similarity index 98% rename from rust-runtime/aws-smithy-http-server/src/logging/service.rs rename to rust-runtime/aws-smithy-http-server/src/instrumentation/service.rs index 8a35e08e45..d358a1e7da 100644 --- a/rust-runtime/aws-smithy-http-server/src/logging/service.rs +++ b/rust-runtime/aws-smithy-http-server/src/instrumentation/service.rs @@ -86,7 +86,7 @@ where /// # Example /// /// ``` -/// # use aws_smithy_http_server::logging::{sensitivity::{*, uri::*, headers::*}, *}; +/// # use aws_smithy_http_server::instrumentation::{sensitivity::{*, uri::*, headers::*}, *}; /// # use tower::{Service, service_fn}; /// # use http::{Request, Response}; /// # async fn f(request: Request<()>) -> Result, ()> { Ok(Response::new(())) } diff --git a/rust-runtime/aws-smithy-http-server/src/lib.rs b/rust-runtime/aws-smithy-http-server/src/lib.rs index 6e34fb1d09..79c963e084 100644 --- a/rust-runtime/aws-smithy-http-server/src/lib.rs +++ b/rust-runtime/aws-smithy-http-server/src/lib.rs @@ -14,7 +14,7 @@ pub mod body; pub(crate) mod error; pub mod extension; #[doc(hidden)] -pub mod logging; +pub mod instrumentation; #[doc(hidden)] pub mod operation; #[doc(hidden)]