Error log server response rejections #2524

david-perez · 2023-03-31T13:42:29Z

All ResponseRejections are errors; the service owners are to blame. So
we centrally log them here to let them know.

Testing

I've applied the following patch

diff --git a/codegen-core/common-test-models/pokemon-common.smithy b/codegen-core/common-test-models/pokemon-common.smithy
index d213a16b1..679ecf2f7 100644
--- a/codegen-core/common-test-models/pokemon-common.smithy
+++ b/codegen-core/common-test-models/pokemon-common.smithy
@@ -38,6 +38,10 @@ structure GetPokemonSpeciesOutput {
     /// A list of flavor text entries for this Pokémon species.
     @required
     flavorTextEntries: FlavorTextEntries
+
+    @required
+    @httpResponseCode
+    responseCode: Integer
 }
 
 /// Retrieve HTTP server statistiscs, such as calls count.
diff --git a/examples/pokemon-service-common/src/lib.rs b/examples/pokemon-service-common/src/lib.rs
index f431270da..ba7636b16 100644
--- a/examples/pokemon-service-common/src/lib.rs
+++ b/examples/pokemon-service-common/src/lib.rs
@@ -190,6 +190,7 @@ pub async fn get_pokemon_species(
             let output = output::GetPokemonSpeciesOutput {
                 name: String::from("pikachu"),
                 flavor_text_entries,
+                response_code: 69,
             };
             Ok(output)
         }

And then we get:

➜  pokemon-service git:(davidpz/error-log-server-response-rejections) ✗ RUST_LOG=error cargo run
Finished dev [unoptimized + debuginfo] target(s) in 0.24s
     Running `/home/ANT.AMAZON.COM/davidpz/code/smithy-ws/src/SmithyRsSource/target/debug/pokemon-service`
Hi com.aws.example#GetPokemonSpecies
{"timestamp":"2023-03-31T12:29:14.816095Z","level":"ERROR","fields":{"e":"Http"},"target":"pokemon_service_server_sdk::operation"}

Upon doing:

➜  aws-smithy-http-server git:(davidpz/error-log-server-response-rejections) ✗ curl -v http://localhost:13734/pokemon-species/pikachu
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 13734 (#0)
> GET /pokemon-species/pikachu HTTP/1.1
> Host: localhost:13734
> User-Agent: curl/7.58.0
> Accept: */*
>
< HTTP/1.1 400 Bad Request
< content-type: application/json
< x-amzn-errortype: SerializationException
< content-length: 2
< date: Fri, 31 Mar 2023 12:29:14 GMT
<
* Connection #0 to host localhost left intact
{}%

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

david-perez · 2023-03-31T13:43:18Z

Note we're just logging the enum variant name, which is not helpful. That will be adressed separately once we properly derive thiserror::Error, see #2517 (comment).

david-perez · 2023-03-31T13:49:13Z

We should also think about having a mechanism to test that the framework is error logging what we expect it to; error logs are very important.

Doing so seems terribly complicated / janky. On one hand the easiest I've found is leveraging tracing_test; on the other hand, we run integration tests for this binary by spawning a child process via Command::cargo_bin("pokemon-service"), so collecting stdout/stderr might suffice.

However, I'm not too keen on doing any of them: the Pokémon Service does not feel like the right place to perform this kind of framework test; its purpose is for users to inspect and copy paste it.

github-actions · 2023-03-31T13:54:33Z

A new generated diff is ready to view.

No codegen difference in the AWS SDK
No codegen difference in the Client Test
No codegen difference in the Server Test
No codegen difference in the Server Test Python

A new doc preview is ready to view.

hlbarber · 2023-04-03T11:48:24Z

...tware/amazon/smithy/rust/codegen/server/smithy/protocols/ServerHttpBoundProtocolGenerator.kt

        rustTemplate(
            """
            impl #{SmithyHttpServer}::response::IntoResponse<#{Marker}> for #{O} {
                fn into_response(self) -> #{SmithyHttpServer}::response::Response {
                    match #{serialize_response}(self) {
                        Ok(response) => response,
-                        Err(e) => #{SmithyHttpServer}::response::IntoResponse::<#{Marker}>::into_response(#{RuntimeError}::from(e))
+                        Err(e) => {
+                            #{Tracing}::error!(%e);


Do we want to add a bit of context here?

error!(error = %e, "failed to serialize response due to internal server error")

We also want to do this for #{E} below?

I added failed to serialize response. "Due to internal server error" will be interpreted as "the framework is to blame".

hlbarber · 2023-04-03T11:50:05Z

This partially addresses #2521

github-actions · 2023-04-03T14:23:33Z

A new generated diff is ready to view.

No codegen difference in the AWS SDK
No codegen difference in the Client Test
No codegen difference in the Server Test
No codegen difference in the Server Test Python

A new doc preview is ready to view.

All `ResponseRejection`s are errors; the service owners are to blame. So we centrally log them here to let them know.

github-actions · 2023-04-04T07:45:52Z

A new generated diff is ready to view.

No codegen difference in the AWS SDK
No codegen difference in the Client Test
Server Test (ignoring whitespace)
No codegen difference in the Server Test Python

A new doc preview is ready to view.

david-perez · 2023-04-04T07:58:11Z

Oh wow this is the first time we add tracing as a dependency of the generated SDKs.

This commit logs server request rejections at the `DEBUG` level in an operation's `FromRequest` implementation. This commit is analogous to the one in PR #2524 for response rejections. However, request rejections are _not_ errors, so they shouldn't be logged at the `ERROR` level. Indeed, they happen every time the server rejects a malformed request. Prior to this commit, the `RuntimeError::NotAcceptable` variant was the only `RuntimeError` variant that was manually constructed. This commit makes it so that it now results from a conversion from a new `RequestRejection::NotAcceptable` variant. We now leverage `futures_util::future::FutureExt::map` to map a future that uses `RequestRejection` as its error into a future that uses `RuntimeError`, and centrally log the rejection there. `futures_util` is already a transitive dependency of server SDKs (via e.g. `hyper` and `tower`), so adding it is a direct dependency is not worse. This helps with #2521.

This commit logs server request rejections at the `DEBUG` level in an operation's `FromRequest` implementation. This commit is analogous to the one in PR #2524 for response rejections. However, request rejections are _not_ errors, so they shouldn't be logged at the `ERROR` level. Indeed, they happen every time the server rejects a malformed request. Prior to this commit, the `RuntimeError::NotAcceptable` variant was the only `RuntimeError` variant that was manually constructed. This commit makes it so that it now results from a conversion from a new `RequestRejection::NotAcceptable` variant. We now leverage `futures_util::future::TryFutureExt::map` to map a future that uses `RequestRejection` as its error into a future that uses `RuntimeError`, and centrally log the rejection there. `futures_util` is already a transitive dependency of server SDKs (via e.g. `hyper` and `tower`), so adding it is a direct dependency is not worse. This helps with #2521. ---- _By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice._

All `ResponseRejection`s are errors; the service owners are to blame. So we centrally log them here to let them know.

This commit logs server request rejections at the `DEBUG` level in an operation's `FromRequest` implementation. This commit is analogous to the one in PR #2524 for response rejections. However, request rejections are _not_ errors, so they shouldn't be logged at the `ERROR` level. Indeed, they happen every time the server rejects a malformed request. Prior to this commit, the `RuntimeError::NotAcceptable` variant was the only `RuntimeError` variant that was manually constructed. This commit makes it so that it now results from a conversion from a new `RequestRejection::NotAcceptable` variant. We now leverage `futures_util::future::TryFutureExt::map` to map a future that uses `RequestRejection` as its error into a future that uses `RuntimeError`, and centrally log the rejection there. `futures_util` is already a transitive dependency of server SDKs (via e.g. `hyper` and `tower`), so adding it is a direct dependency is not worse. This helps with #2521. ---- _By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice._

All `ResponseRejection`s are errors; the service owners are to blame. So we centrally log them here to let them know.

This commit logs server request rejections at the `DEBUG` level in an operation's `FromRequest` implementation. This commit is analogous to the one in PR #2524 for response rejections. However, request rejections are _not_ errors, so they shouldn't be logged at the `ERROR` level. Indeed, they happen every time the server rejects a malformed request. Prior to this commit, the `RuntimeError::NotAcceptable` variant was the only `RuntimeError` variant that was manually constructed. This commit makes it so that it now results from a conversion from a new `RequestRejection::NotAcceptable` variant. We now leverage `futures_util::future::TryFutureExt::map` to map a future that uses `RequestRejection` as its error into a future that uses `RuntimeError`, and centrally log the rejection there. `futures_util` is already a transitive dependency of server SDKs (via e.g. `hyper` and `tower`), so adding it is a direct dependency is not worse. This helps with #2521. ---- _By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice._

@jjant

RPC v2 CBOR is a new protocol that ~is being added~ has [recently been added](https://smithy.io/2.0/additional-specs/protocols/smithy-rpc-v2.html) to the Smithy specification. _(I'll add more details here as the patchset evolves)_ Credit goes to @jjant for initial implementation of the router, which I built on top of from his [`jjant/smithy-rpc-v2-exploration`](https://github.com/awslabs/smithy-rs/tree/jjant/smithy-rpc-v2-exploration) branch. Tracking issue: #3573. ## Caveats `TODO`s are currently exhaustively sprinkled throughout the patch documenting what remains to be done. Most of these need to be addressed before this can be merged in; some can be punted on to not make this PR bigger. However, I'd like to call out the major caveats and blockers here. I'll keep updating this list as the patchset evolves. - [x] RPC v2 has still not been added to the Smithy specification. It is currently being worked on over in the [`smithy-rpc-v2`](https://github.com/awslabs/smithy/tree/smithy-rpc-v2) branch. The following are prerrequisites for this PR to be merged; **until they are done CI on this PR will fail**: - [x] Smithy merges in RPC v2 support. - [x] Smithy releases a new version incorporating RPC v2 support. - Released in [Smithy v1.47](https://github.com/smithy-lang/smithy/releases/tag/1.47.0) - [x] smithy-rs updates to the new version. - Updated in #3552 - [x] ~Protocol tests for the protocol do not currently exist in Smithy. Until those get written~, this PR resorts to Rust unit tests and integration tests that use `serde` to round-trip messages and compare `serde`'s encoders and decoders with ours for correctness. - Protocol tests are under the [`smithy-protocol-tests`](https://github.com/smithy-lang/smithy/tree/main/smithy-protocol-tests/model/rpcv2Cbor) directory in Smithy. - We're keeping the `serde_cbor` round-trip tests for defense in depth. - [ ] #3709 - Currently only server-side support has been implemented, because that's what I'm most familiar. However, we're almost all the way there to add client-side support. - ~[ ] [Smithy `document` shapes](https://smithy.io/2.0/spec/simple-types.html#document) are not supported. RPC v2's specification currently doesn't indicate how to implement them.~ - [The spec](https://smithy.io/2.0/additional-specs/protocols/smithy-rpc-v2.html#shape-serialization) ended up leaving them as unsupported: "Document types are not currently supported in this protocol." ## Prerequisite PRs This section lists prerequisite PRs and issues that would make the diff for this one lighter or easier to understand. It's preferable that these PRs be merged prior to this one; some are hard prerequisites. They mostly relate to parts of the codebase I've had to touch or ~pilfer~ inspect in this PR where I've made necessary changes, refactors and "drive-by improvements" that are mostly unrelated, although some directly unlock things I've needed in this patchset. It makes sense to pull them out to ease reviewability and make this patch more semantically self-contained. - #2516 - #2517 - #2522 - #2524 - #2528 - #2536 - #2537 - #2531 - #2538 - #2539 - #2542 - #3684 - #3678 - #3690 - #3713 - #3726 - #3752 ## Testing    ~RPC v2 has still not been added to the Smithy specification. It is currently being worked on over in the [`smithy-rpc-v2`](https://github.com/awslabs/smithy/tree/smithy-rpc-v2) branch.~ This can only be tested _locally_ following these steps: ~1. Clone [the Smithy repository](https://github.com/smithy-lang/smithy/tree/smithy-rpc-v2) and checkout the `smithy-rpc-v2` branch. 2. Inside your local checkout of smithy-rs pointing to this PR's branch, make sure you've added `mavenLocal()` as a repository in the `build.gradle.kts` files. [Example](8df82fd). 4. Inside your local checkout of Smithy's `smithy-rpc-v2` branch: 1. Set `VERSION` to the current Smithy version used in smithy-rs (1.28.1 as of writing, but [check here](https://github.com/awslabs/smithy-rs/blob/main/gradle.properties#L21)). 2. Run `./gradlew clean build pTML`.~ ~6.~ 1. In your local checkout of the smithy-rs's `smithy-rpc-v2` branch, run `./gradlew codegen-server-test:build -P modules='rpcv2Cbor'`. ~You can troubleshoot whether you have Smithy correctly set up locally by inspecting `~/.m2/repository/software/amazon/smithy/smithy-protocols-traits`.~ ## Checklist  - [ ] I have updated `CHANGELOG.next.toml` if I made changes to the smithy-rs codegen or runtime crates ---- _By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice._

david-perez added the server Rust server SDK label Mar 31, 2023

david-perez requested a review from a team as a code owner March 31, 2023 13:42

david-perez requested review from drganjoo and weihanglo March 31, 2023 13:42

hlbarber approved these changes Apr 3, 2023

View reviewed changes

david-perez mentioned this pull request Apr 3, 2023

Improve the server instrumentation #2521

Open

Error log server response rejections

fd3a6fd

All `ResponseRejection`s are errors; the service owners are to blame. So we centrally log them here to let them know.

david-perez force-pushed the davidpz/error-log-server-response-rejections branch from d9d9efe to fd3a6fd Compare April 4, 2023 07:32

david-perez added this pull request to the merge queue Apr 4, 2023

Merged via the queue into main with commit 421488e Apr 4, 2023

david-perez deleted the davidpz/error-log-server-response-rejections branch April 4, 2023 08:25

david-perez mentioned this pull request Apr 4, 2023

Add server RPC v2 CBOR support #2544

Merged

7 tasks

david-perez mentioned this pull request Apr 19, 2023

DEBUG-log server request rejections #2597

Merged

unexge pushed a commit that referenced this pull request Apr 24, 2023

Error log server response rejections (#2524)

91d0fdc

All `ResponseRejection`s are errors; the service owners are to blame. So we centrally log them here to let them know.

rcoh pushed a commit that referenced this pull request Apr 24, 2023

Error log server response rejections (#2524)

5a2ab77

All `ResponseRejection`s are errors; the service owners are to blame. So we centrally log them here to let them know.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error log server response rejections #2524

Error log server response rejections #2524

david-perez commented Mar 31, 2023

david-perez commented Mar 31, 2023

david-perez commented Mar 31, 2023 •

edited

Loading

github-actions bot commented Mar 31, 2023

hlbarber Apr 3, 2023

hlbarber Apr 3, 2023

david-perez Apr 3, 2023

hlbarber commented Apr 3, 2023

github-actions bot commented Apr 3, 2023

github-actions bot commented Apr 4, 2023

david-perez commented Apr 4, 2023

Error log server response rejections #2524

Error log server response rejections #2524

Conversation

david-perez commented Mar 31, 2023

Testing

david-perez commented Mar 31, 2023

david-perez commented Mar 31, 2023 • edited Loading

github-actions bot commented Mar 31, 2023

hlbarber Apr 3, 2023

Choose a reason for hiding this comment

hlbarber Apr 3, 2023

Choose a reason for hiding this comment

david-perez Apr 3, 2023

Choose a reason for hiding this comment

hlbarber commented Apr 3, 2023

github-actions bot commented Apr 3, 2023

github-actions bot commented Apr 4, 2023

david-perez commented Apr 4, 2023

david-perez commented Mar 31, 2023 •

edited

Loading