Interceptor + TLS auth combination broken after 4d266? #700

cpg314 · 2021-07-07T22:34:41Z

Bug Report

Version

Commits after 4d2667d (not released yet)

Platform

Linux 5.12.13-arch1-2 #1 SMP PREEMPT Fri, 25 Jun 2021 22:56:51 +0000 x86_64 GNU/Linux

Description

I have a simple client with TLS auth (as in https://github.com/hyperium/tonic/tree/master/examples/src/tls_client_auth) and an authentication with interception (as in https://github.com/hyperium/tonic/tree/master/examples/src/authentication).

It works great on 0.4.3.

With 4d2667d, I get the error mentioned in #678, fixed in 2ba0889.

On this latter commit and the next ones, I however get an "Unknown gRPC error" when making a request with the created client. Depending on the commit, it shows as a "transport error" or an "h2 error" (I see that there were some changes in the mapping.
Removing the interceptor (but keeping the TLS auth works fine).

Is it possible that 4d266 broke the interceptor + TLS auth combination?

The text was updated successfully, but these errors were encountered:

cpg314 · 2021-07-08T06:33:31Z

Running with debug logging produces the following output:

[2021-07-08 08:27:33] DEBUG resolving host="localhost"
[2021-07-08 08:27:33] DEBUG connecting to 127.0.0.1:50051
[2021-07-08 08:27:33] DEBUG connected to 127.0.0.1:50051
[2021-07-08 08:27:33] DEBUG No cached session for DNSNameRef("localhost")
[2021-07-08 08:27:33] DEBUG Not resuming any session
[2021-07-08 08:27:33] DEBUG ALPN protocol is Some(b"h2")
[2021-07-08 08:27:33] DEBUG Using ciphersuite TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
[2021-07-08 08:27:33] DEBUG Server supports tickets
[2021-07-08 08:27:33] DEBUG ECDHE curve is ECParameters { curve_type: NamedCurve, named_group: secp256r1 }
[2021-07-08 08:27:33] DEBUG Got CertificateRequest
[2021-07-08 08:27:33] DEBUG Attempting client auth
[2021-07-08 08:27:33] DEBUG Server DNS name is DNSName("localhost")
[2021-07-08 08:27:33] DEBUG Session saved
[2021-07-08 08:27:33] DEBUG binding client connection
[2021-07-08 08:27:33] DEBUG client connection bound
[2021-07-08 08:27:33] DEBUG send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2021-07-08 08:27:33] DEBUG Connection; peer=Client
[2021-07-08 08:27:33] DEBUG received frame=Settings { flags: (0x0), initial_window_size: 4194304, max_frame_size: 4194304, max_header_list_size: 8192 }
[2021-07-08 08:27:33] DEBUG send frame=Settings { flags: (0x1: ACK) }
[2021-07-08 08:27:33] DEBUG received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 4128769 }
[2021-07-08 08:27:33] DEBUG received frame=Ping { ack: false, payload: [0, 0, 0, 0, 0, 0, 0, 0] }
[2021-07-08 08:27:33] DEBUG send frame=Ping { ack: true, payload: [0, 0, 0, 0, 0, 0, 0, 0] }
[2021-07-08 08:27:33] DEBUG send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2021-07-08 08:27:33] DEBUG service.ready=true processing request
[2021-07-08 08:27:33] DEBUG send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2021-07-08 08:27:33] DEBUG send frame=Data { stream_id: StreamId(1) }
[2021-07-08 08:27:33] DEBUG send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2021-07-08 08:27:33] DEBUG received frame=Settings { flags: (0x1: ACK) }
[2021-07-08 08:27:33] DEBUG received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2021-07-08 08:27:33] DEBUG received frame=Reset { stream_id: StreamId(1), error_code: INTERNAL_ERROR }
[2021-07-08 08:27:33] DEBUG received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 36 }
[2021-07-08 08:27:33] DEBUG client response error: protocol error: unexpected internal error encountered
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Status { code: Unknown, message: "transport error", source: None }', src/main.rs:54:10

So it looks like it connects, but the server sends an internal error? I'm using an empty interceptor to test, and it works fine without it, i.e.
let mut client = EchoClient::channel(channel);
instead of

let mut client = EchoClient::with_interceptor(channel, move |mut req: Request<()>| {
        Ok(req)
    });

Here's what happens on the server:

I0708 08:43:21.618545349 1427336 call.cc:633]                OP[server:0x7f95a4031290]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618550848 1427336 channel_stack.cc:226]       OP[server-auth:0x7f95a40312a8]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618555685 1427336 channel_stack.cc:226]       OP[message_size:0x7f95a40312c0]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618560417 1427336 channel_stack.cc:226]       OP[deadline:0x7f95a40312d8]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618565102 1427336 channel_stack.cc:226]       OP[http-server:0x7f95a40312f0]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618569990 1427336 channel_stack.cc:226]       OP[message_decompress:0x7f95a4031308]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618574618 1427336 channel_stack.cc:226]       OP[message_compress:0x7f95a4031320]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618579365 1427336 channel_stack.cc:226]       OP[connected:0x7f95a4031338]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618583967 1427336 chttp2_transport.cc:1656]   perform_stream_op[s=0x7f95a40321e0]:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}
I0708 08:43:21.618588928 1427336 call.cc:580]                grpc_call_unref(c=0x7f95a4030920)
I0708 08:43:21.618593461 1427336 timer_generic.cc:367]       TIMER 0x7f95a4016208: SET 7203421 now 3421 call 0x7f95a4016188[0x7f95e1e59b00]
I0708 08:43:21.618597084 1427336 timer_generic.cc:404]         .. add to shard 20 with queue_deadline_cap=4002 => is_first_timer=false
I0708 08:43:21.618600852 1427336 chttp2_transport.cc:1358]   perform_stream_op_locked:  CANCEL:{"created":"@1625726601.618531273","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":1060,"referenced_errors":[{"created":"@1625726601.618530290","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":121,"referenced_errors":[{"created":"@1625726601.618529381","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":202,"key":"te"}]}]}; on_complete = 0x7f95a4022b10

Googling for this last error, it seems to match stepancheg/grpc-rust#105, and the server is also a Python one.

cpg314 · 2021-07-08T07:37:53Z

I'm looking at https://github.com/hyperium/tonic/blob/master/tonic/src/client/grpc.rs#L252 and it seems the right headers are set for compatibility with python servers.
Is it possible that the new interceptor implementation skips these, which would explain why it works without, but not with the trivial interceptor?

davidpdrsn · 2021-07-08T08:07:01Z

Are you able to provide an example script that reproduces the error?

cpg314 · 2021-07-08T09:07:21Z

Good news, I've found the issue :)

https://github.com/hyperium/tonic/blob/e1993877c430906500aeda9ab1e3413e68ed483d/tonic/src/client/grpc.rs sets the headers right
Then

tonic/tonic/src/service/interceptor.rs

Line 118 in 2ba0889

let req = req.into_http(uri);

is called to transform the request when an interceptor is used
There, into_http "sanitizes" the header, namely removes the gRPC headers

tonic/tonic/src/request.rs

Line 175 in e199387

*request.headers_mut() = self.metadata.into_sanitized_headers();

It works fine when removing the sanitization, but there is probably a more elegant solution.

davidpdrsn · 2021-07-08T09:15:18Z

I'm still not sure I get what the actual issue is. I tried applying interceptors to the tls-client-auth examples but they both work fine.

Are you able to provide a reproduction script?

cpg314 · 2021-07-08T09:20:00Z

Try to print the request in grpc,rs and then in

tonic/tonic/src/transport/channel/mod.rs

Line 189 in e199387

fn call(&mut self, request: http::Request<BoxBody>) -> Self::Future {

just before it gets made:

Request { method: POST, uri: /..., version: HTTP/2.0, headers: {"te": "trailers", "content-type": "application/grpc"}, body: BoxBody }
Request { method: POST, uri: /..., version: HTTP/2.0, headers: {}, body: BoxBody }

The headers (that are necessary to interact with a Python server). get dropped because of the into_http implementation in the interceptor.

davidpdrsn · 2021-07-08T09:27:27Z

Ah yeah I see. All the talk about TLS made it seem like the problem was something else.

I'll look into it, shouldn't be hard to fix.

`InterceptedService` would previously use `tonic::Request::into_http` which removes reserved headers. That mean inner middleware in the stack wouldn't be able to see those headers, which could result in errors. Fixes #700

davidpdrsn · 2021-07-08T09:55:35Z

@cpg314 Are you able to see if #701 fixes the issue?

cpg314 · 2021-07-08T10:05:41Z

It does, thanks a lot for the quick fix!

`InterceptedService` would previously use `tonic::Request::into_http` which removes reserved headers. That mean inner middleware in the stack wouldn't be able to see those headers, which could result in errors. Fixes #700

davidpdrsn added A-tonic C-bug Category: Something isn't working labels Jul 8, 2021

davidpdrsn added this to the 0.5 milestone Jul 8, 2021

davidpdrsn mentioned this issue Jul 8, 2021

fix(tonic): don't remove reserved headers in interceptor #701

Merged

LucioFranco closed this as completed in #701 Jul 8, 2021

NAlexPear mentioned this issue Nov 18, 2021

Content-Type missing in responses triggered by interceptors returning Status #840

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Interceptor + TLS auth combination broken after 4d266? #700

Interceptor + TLS auth combination broken after 4d266? #700

cpg314 commented Jul 7, 2021 •

edited

cpg314 commented Jul 8, 2021 •

edited

cpg314 commented Jul 8, 2021

davidpdrsn commented Jul 8, 2021

cpg314 commented Jul 8, 2021 •

edited

davidpdrsn commented Jul 8, 2021

cpg314 commented Jul 8, 2021

davidpdrsn commented Jul 8, 2021

davidpdrsn commented Jul 8, 2021

cpg314 commented Jul 8, 2021

Interceptor + TLS auth combination broken after 4d266? #700

Interceptor + TLS auth combination broken after 4d266? #700

Comments

cpg314 commented Jul 7, 2021 • edited

Bug Report

Version

Platform

Description

cpg314 commented Jul 8, 2021 • edited

cpg314 commented Jul 8, 2021

davidpdrsn commented Jul 8, 2021

cpg314 commented Jul 8, 2021 • edited

davidpdrsn commented Jul 8, 2021

cpg314 commented Jul 8, 2021

davidpdrsn commented Jul 8, 2021

davidpdrsn commented Jul 8, 2021

cpg314 commented Jul 8, 2021

cpg314 commented Jul 7, 2021 •

edited

cpg314 commented Jul 8, 2021 •

edited

cpg314 commented Jul 8, 2021 •

edited