h2 protocol error

828 views

Skip to first unread message

rng...@vsco.co

unread,

Apr 11, 2018, 2:54:16 AM4/11/18

to envoy-users

Hi, I've been testing out using a two Envoy setup like so:

client --- envoy1 proxy --- envoy2 proxy --- app/service

The client is creatinga H2 connection to make GRPC requests. I am seeing periodic spikes (maybe once or twice and hour during the day) in 503 UC in the envoy1 access logs. That same request can be seen in the envoy2 access logs with a HTTP response of 0. The request doesn’t make it to the service.

After doing some debugging, what I can see is that envoy2 closes the connection between itself and envoy1 because of the error “invalid frame: Protocol Error”

I’m not sure if this is something between two Envoys or because of a malformed request. But I assume (maybe incorrectly) that if it was the latter, envoy1 would be catching it and the request wouldn’t make it’s way to envoy2.

My question is has anyone run into this and if there is any tips on where to start looking or debugging.

I’ve attached both envoy configs and some trace logs. Using Envoy 1.5 on both proxies BUT envoy2 is using API v1 because we haven’t had time to move it to API v2 yet. If anyone thinks that could be the issue I could spend some time to move it to v2.

envoy 1 config:

static_resources:

listeners:

- name: ingress_grpc

address:

socket_address:

address: 0.0.0.0

port_value: 6555

protocol: tcp

filter_chains:

- tls_context:

common_tls_context:

alpn_protocols: h2,http/1.1

tls_certificates:

- certificate_chain: { filename: "/usr/local/envoy/certs/star.chain.full.pem" }

private_key: { filename: "/usr/local/envoy/certs/star.key" }

filters:

- name: envoy.http_connection_manager

config:

idle_timeout: { seconds: 600 }

add_user_agent: true

codec_type: http2

stat_prefix: ingress_grpc

use_remote_address: true

route_config:

name: local_route

virtual_hosts:

- name: app1

domains: ["*"]

routes:

- match: { prefix: "/" }

route:

cluster: envoy2

timeout: { seconds: 0 }

http_filters:

- name: envoy.router

clusters:

- name: envoy2

connect_timeout: 100s

lb_policy: ROUND_ROBIN

type: LOGICAL_DNS

http2_protocol_options: {}

max_requests_per_connection: 25000

hosts:

- socket_address:

address: envoy2

port_value: 8000

protocol: tcp

envoy 2 config

"cluster_manager": {

"clusters": [

{

"hosts": [

{

"url": "tcp://10.43.228.229:5461"

}

"features": "http2",

"lb_type": "least_request",

"type": "sds",

"connect_timeout_ms": 500,

"name": "app",

"service_name": "app",

"circuit_breakers": {

"default": {

"max_connections": 64000

}

]

"listeners": [

{

"address": "tcp://0.0.0.0:6555",

"filters": [

{

"config": {

"filters": [

{

"config": {

"max_request_time_s": 120,

"max_request_bytes": 52242880

"name": "buffer",

"type": "decoder"

{

"config": {},

"name": "router",

"type": "decoder"

}

"codec_type": "auto",

"add_user_agent": true,

"idle_timeout_s": 840,

"stat_prefix": "ingress_grpc",

"use_remote_address": false,

"route_config": {

"virtual_hosts": [

{

"routes": [

{

"prefix": "/",

"cluster": "app",

"timeout_ms": 0

}

"domains": ["*"],

"name": "app"

}

]

}

"name": "http_connection_manager",

"type": "read"

}

]

}

]

log snippet:

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:181] [C138587] new stream

[2018-04-08 15:21:10.665][10][trace][http2] source/common/http/http2/codec_impl.cc:354] [C138587] recv frame type=1

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:439] [C138587][S13071016848429935624] request headers complete (end_stream=false):

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] ':scheme':'http'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] ':method':'POST'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] ':authority':'app:6555'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] ':path':'/app.App/Stream'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'user-agent':'grpc-java-okhttp/0.0'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'content-type':'application/grpc'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'te':'trailers'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'authorization':'xxxxxxxxxxxxxxxxxxx'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'language':'en'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'grpc-accept-encoding':'gzip'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'x-forwarded-for':'1.1.1.1'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'x-forwarded-proto':'https'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'x-envoy-downstream-service-cluster':'envoy1'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'x-envoy-downstream-service-node':'envoy1'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'x-envoy-external-address':'0.0.0.0'

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:444] [C138587][S13071016848429935624] 'x-request-id':'341f0c2d-6147-44cf-88ea-b02e04d7fc44'

[2018-04-08 15:21:10.665][10][trace][http] source/common/http/conn_manager_impl.cc:622] [C138587][S13071016848429935624] decode headers called: filter=0x33f06c0 status=0

[2018-04-08 15:21:10.665][10][trace][http] source/common/http/conn_manager_impl.cc:622] [C138587][S13071016848429935624] decode headers called: filter=0x35a27c0 status=1

[2018-04-08 15:21:10.665][10][trace][http2] source/common/http/http2/codec_impl.cc:354] [C138587] recv frame type=0

[2018-04-08 15:21:10.665][10][debug][http] source/common/http/conn_manager_impl.cc:652] [C138587][S13071016848429935624] request end stream

[2018-04-08 15:21:10.665][10][trace][http] source/common/http/conn_manager_impl.cc:679] [C138587][S13071016848429935624] decode data called: filter=0x33f06c0 status=0

[2018-04-08 15:21:10.665][10][trace][http] source/common/http/conn_manager_impl.cc:679] [C138587][S13071016848429935624] decode data called: filter=0x35a27c0 status=0

[2018-04-08 15:21:10.665][10][trace][http] source/common/http/conn_manager_impl.cc:1029] [C138587][S13071016848429935624] continuing filter chain: filter=0x35a27c0

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:239] [C138587][S13071016848429935624] cluster 'app' match for URL '/app.App/Stream'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] ':scheme':'http'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] ':method':'POST'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] ':authority':'app'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] ':path':'/app.App/Stream'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'user-agent':'grpc-java-okhttp/0.0'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'content-type':'application/grpc'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'te':'trailers'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'authorization':'xxxxxxxxxxxxxxxxxxx'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'language':'en'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'grpc-accept-encoding':'gzip'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'x-forwarded-for':'1.1.1.1'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'x-forwarded-proto':'https'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'x-envoy-downstream-service-cluster':'envoy2'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'x-envoy-downstream-service-node':'envoy2'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'x-envoy-external-address':'0.0.0.0'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:284] [C138587][S13071016848429935624] 'x-request-id':'341f0c2d-6147-44cf-88ea-b02e04d7fc44'

[2018-04-08 15:21:10.665][10][debug][router] source/common/router/router.cc:902] [C138587][S13071016848429935624] pool ready

[2018-04-08 15:21:10.665][10][trace][http] source/common/http/conn_manager_impl.cc:622] [C138587][S13071016848429935624] decode headers called: filter=0x39f3500 status=1

[2018-04-08 15:21:10.665][10][trace][router] source/common/router/router.cc:818] [C138587][S13071016848429935624] proxying 5 bytes

[2018-04-08 15:21:10.665][10][trace][http] source/common/http/conn_manager_impl.cc:679] [C138587][S13071016848429935624] decode data called: filter=0x39f3500 status=3

[2018-04-08 15:21:10.665][10][trace][http2] source/common/http/http2/codec_impl.cc:309] [C138587] dispatched 176 bytes

[2018-04-08 15:21:10.958][10][trace][connection] source/common/network/connection_impl.cc:363] [C138587] socket event: 3

[2018-04-08 15:21:10.958][10][trace][connection] source/common/network/connection_impl.cc:485] [C138587] write ready

[2018-04-08 15:21:10.958][10][trace][connection] source/common/network/connection_impl.cc:439] [C138587] read ready

[2018-04-08 15:21:10.958][10][trace][connection] source/common/network/connection_impl.cc:412] [C138587] read returns: 13

[2018-04-08 15:21:10.958][10][trace][connection] source/common/network/connection_impl.cc:412] [C138587] read returns: -1

[2018-04-08 15:21:10.958][10][trace][connection] source/common/network/connection_impl.cc:420] [C138587] read error: 11

[2018-04-08 15:21:10.958][10][trace][http2] source/common/http/http2/codec_impl.cc:294] [C138587] dispatching 13 bytes

[2018-04-08 15:21:10.958][10][debug][http2] source/common/http/http2/codec_impl.cc:494] [C138587] invalid frame: Protocol error

[2018-04-08 15:21:10.958][10][debug][http] source/common/http/conn_manager_impl.cc:225] [C138587] dispatch error: The user callback function failed

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S13071016848429935624] resetting pool request

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S6622079771232605952] resetting pool request

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S6633390131697699051] resetting pool request

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S15725616439296296044] resetting pool request

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S16824365358774997167] resetting pool request

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S6915390084269767185] resetting pool request

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S16308279489100182832] resetting pool request

[2018-04-08 15:21:10.958][10][debug][router] source/common/router/router.cc:856] [C138587][S8845831177606090622] resetting pool request

Matt Klein

unread,

Apr 11, 2018, 12:40:53 PM4/11/18

to rng...@vsco.co, envoy-users

Hmm. This is an interesting one. I don't have any ideas off the top of head. I agree that between the Envoys we should not be seeing this. I think it would be good to open an issue on this and we can discuss there. But a few quick questions:

1) Are you able to repo on demand? (I can't imagine you are running at trace level logging for an hour to capture this but maybe?)

2) Do you have the envoy1 logs that match this?

3) Do you have any idea of whether this is a fresh connection between envoy1 and envoy2 or it has been open for a while?

re: debugging, unfortunately in the invalid frame callback from nghttp2 there is not access to the extended debug data. Ironically, this data is written into the GOAWAY frame sent to envoy1, which we should probably log if available which might help.

Anyway, I don't have any great ideas right now but definitely interested in getting to the bottom of this.

--
You received this message because you are subscribed to the Google Groups "envoy-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to envoy-users+unsubscribe@googlegroups.com.
To post to this group, send email to envoy...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/envoy-users/9abcdca9-abbb-4838-97bc-1f010ac34a1b%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Matt Klein

Software Engineer

mkl...@lyft.com

https://calendly.com/mattklein123

rng...@vsco.co

unread,

Apr 12, 2018, 1:51:55 PM4/12/18

to envoy-users

Thanks for the response Matt, I’ll keep digging away at this and post here if I come up with anything.

rng...@vsco.co

unread,

Apr 12, 2018, 1:54:03 PM4/12/18

to envoy-users

Oh to answer your questions. I haven’t been able to repro on demand and I believe based on the logs these are fresh connections.

I’ll open an issue on github as well. Thanks!

rng...@vsco.co

unread,

Apr 25, 2018, 5:18:28 PM4/25/18

to envoy-users

Just circling back here, it turns out that we ran into this issue here:

https://github.com/envoyproxy/envoy/issues/3076

And setting the max concurrent streams on the listener solved the issue.

Reply all

Reply to author

Forward

0 new messages