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.

Sign up for GitHub

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

Jump to bottom

ext_authz gRPC with a request body may be called multiple times for the same request #13260

Closed
brectanus-sigsci opened this issue Sep 24, 2020 · 7 comments · Fixed by #13288
Closed

ext_authz gRPC with a request body may be called multiple times for the same request #13260

brectanus-sigsci opened this issue Sep 24, 2020 · 7 comments · Fixed by #13288
Assignees
@dio
Labels
area/ext_authz bug help wanted Needs help!
Milestone
1.17.0

Comments

@brectanus-sigsci
Copy link
Contributor

Description:

When (at least gRPC) ext_authz is configured to send the body, the gRPC service may receive multiple calls for the same HTTP request if there is a larger body than the limit and that body spans multiple buffers. This seems to be due to the call being triggered on buffer flushes, so that each buffer flush triggers an ext_auth call, but I have not had a chance to dig in further.

Repro steps:

Configure ext_auth to a gRPC cluster:

- name: envoy.ext_authz
  config:
    grpc_service:
      envoy_grpc:
        cluster_name: my-grpc-cluster
      timeout: 0.2s
    failure_mode_allow: true
    with_request_body:
      max_request_bytes: 1048576
      allow_partial_message: true

Send a request larger than the body limit:

# ~15MB text file
dd if=/dev/urandom bs=1m count=10 | base64 > test.txt
# Send the large file via curl to the envoy-proxy listener
curl -F file=@test.txt 'http://envoy-proxy/'

I expect that the gRPC service is called a single time with up to the limit bytes in the body. However what I am seeing is the gRPC service being called multiple times, each with part of the body at different points. Additionally the size parameter indicating the body size is not the size of the body included in that call, but rather the bytes received so far.

Below you can see trace level logs showing 3 calls to /envoy.service.auth.v2.Authorization/Check from a single curl call above.

Config:

See above.

Logs:

envoy-proxy_1  | [2020-09-24 19:40:36.672307000][16][debug][conn_handler] [C0] new connection
envoy-proxy_1  | [2020-09-24 19:40:36.672721000][16][debug][http] [C0] new stream
envoy-proxy_1  | [2020-09-24 19:40:36.672923000][16][debug][http] [C0][S17124157035306136726] request headers complete (end_stream=false):
envoy-proxy_1  | ':authority', 'envoy-proxy'
envoy-proxy_1  | ':path', '/'
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | 'user-agent', 'curl/7.71.1'
envoy-proxy_1  | 'accept', '*/*'
envoy-proxy_1  | 'content-length', '15379308'
envoy-proxy_1  | 'content-type', 'multipart/form-data; boundary=------------------------3b7eab24599a4700'
envoy-proxy_1  | 'expect', '100-continue'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:36.673366000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter is buffering the request
envoy-proxy_1  | [2020-09-24 19:40:36.702327000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.704459000][16][debug][router] [C0][S16859111074799485479] cluster 'my-grpc-cluster' match for URL '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | [2020-09-24 19:40:36.704763000][16][debug][router] [C0][S16859111074799485479] router decoding headers:
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | ':path', '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | ':authority', 'my-grpc-cluster'
envoy-proxy_1  | ':scheme', 'http'
envoy-proxy_1  | 'te', 'trailers'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'x-b3-traceid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-spanid', '2f3798c362498339'
envoy-proxy_1  | 'x-b3-parentspanid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-sampled', '0'
envoy-proxy_1  | 'x-envoy-internal', 'true'
envoy-proxy_1  | 'x-forwarded-for', '172.18.0.4'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:36.704821000][16][debug][pool] queueing stream due to no available connections
envoy-proxy_1  | [2020-09-24 19:40:36.704845000][16][debug][pool] creating a new connection
envoy-proxy_1  | [2020-09-24 19:40:36.704918000][16][debug][client] [C1] connecting
envoy-proxy_1  | [2020-09-24 19:40:36.705396000][16][debug][connection] [C1] connecting to 172.18.0.3:8085
envoy-proxy_1  | [2020-09-24 19:40:36.705876000][16][debug][connection] [C1] connection in progress
envoy-proxy_1  | [2020-09-24 19:40:36.706782000][16][debug][http2] [C1] updating connection-level initial window size to 268435456
envoy-proxy_1  | [2020-09-24 19:40:36.708133000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.708417000][16][debug][connection] [C1] connected
envoy-proxy_1  | [2020-09-24 19:40:36.708552000][16][debug][client] [C1] connected
envoy-proxy_1  | [2020-09-24 19:40:36.708801000][16][debug][pool] [C1] attaching to next stream
envoy-proxy_1  | [2020-09-24 19:40:36.709068000][16][debug][pool] [C1] creating stream
envoy-proxy_1  | [2020-09-24 19:40:36.709428000][16][debug][router] [C0][S16859111074799485479] pool ready
envoy-proxy_1  | [2020-09-24 19:40:36.710117000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.711631000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.712141000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.714305000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.715849000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.723405000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.723989000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.724869000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.726354000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.726606000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.727896000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.728618000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.731127000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.731918000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.734262000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.735771000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.736241000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.737143000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.737719000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.738723000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.739112000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.740459000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.740665000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.742278000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.742705000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.743664000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.743935000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.745288000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.746743000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.747599000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.748119000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.749387000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.750058000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.751586000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.752624000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.755605000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.755942000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.756990000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.757317000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.758646000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.759042000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.760941000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.761298000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.762874000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.763394000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.765835000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.767612000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.768529000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.769573000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.770077000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.771700000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.772264000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.774725000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.776552000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.778019000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.779470000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.780140000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.781678000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.783036000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.784406000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.785584000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.786933000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.788287000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.788606000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.789795000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.790204000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.794967000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.795827000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.797325000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.806498000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.808799000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.809425000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.812255000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.812719000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.814622000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.815665000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.817930000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.818276000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.819461000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.824882000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.826768000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.828376000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.829850000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.855857000][16][debug][client] [C1] response complete
envoy-proxy_1  | [2020-09-24 19:40:36.855946000][16][debug][pool] [C1] destroying stream: 0 remaining
envoy-proxy_1  | [2020-09-24 19:40:36.855984000][16][debug][router] [C0][S16859111074799485479] upstream headers complete: end_stream=true
envoy-proxy_1  | [2020-09-24 19:40:36.856554000][16][debug][http] async http request response headers (end_stream=true):
envoy-proxy_1  | ':status', '200'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'grpc-status', '2'
envoy-proxy_1  | 'grpc-message', 'prerequest timed out'
envoy-proxy_1  | 'x-envoy-upstream-service-time', '148'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:36.856696000][16][debug][router] [C0][S17124157035306136726] cluster 'http-test-server' match for URL '/'
envoy-proxy_1  | [2020-09-24 19:40:36.856833000][16][debug][router] [C0][S17124157035306136726] router decoding headers:
envoy-proxy_1  | ':authority', 'envoy-proxy'
envoy-proxy_1  | ':path', '/'
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | ':scheme', 'http'
envoy-proxy_1  | 'user-agent', 'curl/7.71.1'
envoy-proxy_1  | 'accept', '*/*'
envoy-proxy_1  | 'content-length', '15379308'
envoy-proxy_1  | 'content-type', 'multipart/form-data; boundary=------------------------3b7eab24599a4700'
envoy-proxy_1  | 'x-forwarded-proto', 'http'
envoy-proxy_1  | 'x-request-id', '2e8b8750-fff5-40c4-ab80-a3fe0564b72f'
envoy-proxy_1  | 'x-envoy-expected-rq-timeout-ms', '15000'
envoy-proxy_1  | 'x-b3-traceid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-spanid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-sampled', '0'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:36.856868000][16][debug][pool] queueing stream due to no available connections
envoy-proxy_1  | [2020-09-24 19:40:36.856893000][16][debug][pool] creating a new connection
envoy-proxy_1  | [2020-09-24 19:40:36.856973000][16][debug][client] [C2] connecting
envoy-proxy_1  | [2020-09-24 19:40:36.856981000][16][debug][connection] [C2] connecting to 172.18.0.2:8801
envoy-proxy_1  | [2020-09-24 19:40:36.857375000][16][debug][connection] [C2] connection in progress
envoy-proxy_1  | [2020-09-24 19:40:36.857607000][16][debug][http2] [C1] stream closed: 0
envoy-proxy_1  | [2020-09-24 19:40:36.857650000][16][debug][connection] [C2] connected
envoy-proxy_1  | [2020-09-24 19:40:36.857658000][16][debug][client] [C2] connected
envoy-proxy_1  | [2020-09-24 19:40:36.857743000][16][debug][pool] [C2] attaching to next stream
envoy-proxy_1  | [2020-09-24 19:40:36.857753000][16][debug][pool] [C2] creating stream
envoy-proxy_1  | [2020-09-24 19:40:36.857762000][16][debug][router] [C0][S17124157035306136726] pool ready
envoy-proxy_1  | [2020-09-24 19:40:36.857832000][16][debug][http] [C0][S17124157035306136726] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:36.857869000][16][debug][http] [C0][S17124157035306136726] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:36.857878000][16][debug][connection] [C2] onAboveWriteBufferHighWatermark
envoy-proxy_1  | [2020-09-24 19:40:36.857882000][16][debug][http] [C0][S17124157035306136726] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:36.910528000][16][debug][connection] [C2] onBelowWriteBufferLowWatermark
envoy-proxy_1  | [2020-09-24 19:40:36.910554000][16][debug][http] [C0][S17124157035306136726] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:36.941190000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.943207000][16][debug][router] [C0][S5964425306993751386] cluster 'my-grpc-cluster' match for URL '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | [2020-09-24 19:40:36.943291000][16][debug][router] [C0][S5964425306993751386] router decoding headers:
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | ':path', '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | ':authority', 'my-grpc-cluster'
envoy-proxy_1  | ':scheme', 'http'
envoy-proxy_1  | 'te', 'trailers'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'x-b3-traceid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-spanid', '4b4d76176318e662'
envoy-proxy_1  | 'x-b3-parentspanid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-sampled', '0'
envoy-proxy_1  | 'x-envoy-internal', 'true'
envoy-proxy_1  | 'x-forwarded-for', '172.18.0.4'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:36.943325000][16][debug][pool] [C1] using existing connection
envoy-proxy_1  | [2020-09-24 19:40:36.943347000][16][debug][pool] [C1] creating stream
envoy-proxy_1  | [2020-09-24 19:40:36.943361000][16][debug][router] [C0][S5964425306993751386] pool ready
envoy-proxy_1  | [2020-09-24 19:40:36.944000000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.944820000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.945677000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.948365000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.949578000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.950975000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.952128000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.952713000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.953705000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.954059000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.955731000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.956879000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.958320000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.959238000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.960906000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.962035000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.962527000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.963827000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.965027000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.965568000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.967065000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.968740000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.970831000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.971688000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.973111000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.974295000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.974800000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.977061000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.978120000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.978845000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.980854000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.980949000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.982588000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.983747000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.990621000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.992372000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.992705000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.993242000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.993822000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:36.997390000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.003689000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.004372000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.005903000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.006619000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.007261000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.009792000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.011604000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.013002000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.013294000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.014208000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.014782000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.016277000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.016323000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.019130000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.020472000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.020805000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.022440000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.022888000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.024179000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.025965000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.027383000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.028930000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.031642000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.031762000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.034054000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.037022000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.038213000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.039519000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.040787000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.041419000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.042932000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.044078000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.046068000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.047474000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.047998000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.049244000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.051620000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.053299000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.055129000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.055564000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.056716000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.057157000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.058412000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.059888000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.061636000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.062713000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.065445000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.067082000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.068250000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.069664000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.072388000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.075790000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.076632000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.077891000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.079384000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.080070000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.081813000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.084510000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.085322000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.087724000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.088590000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.095882000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.098375000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.101622000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.103614000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.105457000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.109363000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.110812000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.113672000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.119984000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.137251000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.138281000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.141632000][16][debug][router] [C0][S5964425306993751386] resetting pool request
envoy-proxy_1  | [2020-09-24 19:40:37.141702000][16][debug][client] [C1] request reset
envoy-proxy_1  | [2020-09-24 19:40:37.141715000][16][debug][pool] [C1] destroying stream: 0 remaining
envoy-proxy_1  | [2020-09-24 19:40:37.141740000][16][debug][http2] [C1] sent reset code=0
envoy-proxy_1  | [2020-09-24 19:40:37.141744000][16][debug][http2] [C1] stream closed: 0
envoy-proxy_1  | [2020-09-24 19:40:37.141947000][16][debug][http] [C0][S17124157035306136726] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.142063000][16][debug][http] [C0][S17124157035306136726] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.142077000][16][debug][connection] [C2] onAboveWriteBufferHighWatermark
envoy-proxy_1  | [2020-09-24 19:40:37.142082000][16][debug][http] [C0][S17124157035306136726] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.169800000][16][debug][connection] [C2] onBelowWriteBufferLowWatermark
envoy-proxy_1  | [2020-09-24 19:40:37.170630000][16][debug][http] [C0][S17124157035306136726] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.200354000][8][debug][main] flushing stats
envoy-proxy_1  | [2020-09-24 19:40:37.205874000][8][debug][upstream] transport socket match, socket default selected for host with address 172.18.0.3:8085
envoy-proxy_1  | [2020-09-24 19:40:37.205951000][8][debug][upstream] DNS refresh rate reset for my-grpc-cluster, refresh rate 5000 ms
envoy-proxy_1  | [2020-09-24 19:40:37.205972000][8][debug][upstream] transport socket match, socket default selected for host with address 172.18.0.2:8801
envoy-proxy_1  | [2020-09-24 19:40:37.205981000][8][debug][upstream] DNS refresh rate reset for http-test-server, refresh rate 5000 ms
envoy-proxy_1  | [2020-09-24 19:40:37.206093000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.208016000][16][debug][router] [C0][S13429545399195052272] cluster 'my-grpc-cluster' match for URL '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | [2020-09-24 19:40:37.208083000][16][debug][router] [C0][S13429545399195052272] router decoding headers:
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | ':path', '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | ':authority', 'my-grpc-cluster'
envoy-proxy_1  | ':scheme', 'http'
envoy-proxy_1  | 'te', 'trailers'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'x-b3-traceid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-spanid', '890145facdc20fd4'
envoy-proxy_1  | 'x-b3-parentspanid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-sampled', '0'
envoy-proxy_1  | 'x-envoy-internal', 'true'
envoy-proxy_1  | 'x-forwarded-for', '172.18.0.4'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:37.208098000][16][debug][pool] [C1] using existing connection
envoy-proxy_1  | [2020-09-24 19:40:37.208180000][16][debug][pool] [C1] creating stream
envoy-proxy_1  | [2020-09-24 19:40:37.208225000][16][debug][router] [C0][S13429545399195052272] pool ready
envoy-proxy_1  | [2020-09-24 19:40:37.217708000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.219641000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.222315000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.223750000][8][debug][upstream] DNS refresh rate reset for jaeger, (failure) refresh rate 5000 ms
envoy-proxy_1  | [2020-09-24 19:40:37.224530000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.225455000][8][debug][upstream] DNS refresh rate reset for fortio-server, (failure) refresh rate 5000 ms
envoy-proxy_1  | [2020-09-24 19:40:37.225523000][8][debug][upstream] DNS refresh rate reset for nighthawk-test-server, (failure) refresh rate 5000 ms
envoy-proxy_1  | [2020-09-24 19:40:37.225572000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.226842000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.228801000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.229921000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.230655000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.233636000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.235088000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.235853000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.237676000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.239930000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.240920000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.241959000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.245321000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.246718000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.247510000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.248742000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.249587000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.252302000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.252540000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.254421000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.255294000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.256594000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.258611000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.258841000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.260434000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.261527000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.263117000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.264916000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.267253000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.268534000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.270625000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.271722000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.273273000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.273427000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.275689000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.277531000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.279232000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.280934000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.281583000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.284214000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.284606000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.287953000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.289278000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.290442000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.292387000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.293000000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.294953000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.296395000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.298552000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.300269000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.300795000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.302653000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.303392000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.305110000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.306130000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.307878000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.309023000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.311385000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.312457000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.313899000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.314711000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.315992000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.317261000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.318788000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.319845000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.321818000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.322419000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.324239000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.325412000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.327758000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.328854000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.330518000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.330842000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.332756000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.333593000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.335666000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.335997000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.337758000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.338474000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.339336000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.339453000][16][debug][http] [C0][S17124157035306136726] request end stream
envoy-proxy_1  | [2020-09-24 19:40:37.339468000][16][debug][filter] [C0][S17124157035306136726] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-24 19:40:37.386779000][16][debug][client] [C1] response complete
envoy-proxy_1  | [2020-09-24 19:40:37.386797000][16][debug][pool] [C1] destroying stream: 0 remaining
envoy-proxy_1  | [2020-09-24 19:40:37.386839000][16][debug][router] [C0][S13429545399195052272] upstream headers complete: end_stream=true
envoy-proxy_1  | [2020-09-24 19:40:37.386906000][16][debug][http] async http request response headers (end_stream=true):
envoy-proxy_1  | ':status', '200'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'grpc-status', '2'
envoy-proxy_1  | 'grpc-message', 'prerequest timed out'
envoy-proxy_1  | 'x-envoy-upstream-service-time', '178'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:37.387060000][16][debug][http] [C0][S17124157035306136726] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.387133000][16][debug][http] [C0][S17124157035306136726] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.387231000][16][debug][connection] [C2] onAboveWriteBufferHighWatermark
envoy-proxy_1  | [2020-09-24 19:40:37.387238000][16][debug][http] [C0][S17124157035306136726] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.387267000][16][debug][http2] [C1] stream closed: 0
envoy-proxy_1  | [2020-09-24 19:40:37.395779000][16][debug][connection] [C2] onBelowWriteBufferLowWatermark
envoy-proxy_1  | [2020-09-24 19:40:37.395820000][16][debug][http] [C0][S17124157035306136726] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-24 19:40:37.397237000][16][debug][router] [C0][S17124157035306136726] upstream headers complete: end_stream=false
envoy-proxy_1  | [2020-09-24 19:40:37.397495000][16][debug][http] [C0][S17124157035306136726] encoding headers via codec (end_stream=false):
envoy-proxy_1  | ':status', '200'
envoy-proxy_1  | 'date', 'Thu, 24 Sep 2020 19:40:37 GMT'
envoy-proxy_1  | 'content-length', '49'
envoy-proxy_1  | 'content-type', 'text/plain; charset=utf-8'
envoy-proxy_1  | 'x-envoy-upstream-service-time', '10'
envoy-proxy_1  | 'x-b3-traceid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-b3-spanid', '0c5c3f1d3c4317a7'
envoy-proxy_1  | 'x-request-id', '2e8b8750-fff5-40c4-ab80-a3fe0564b72f'
envoy-proxy_1  | 'server', 'envoy'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-24 19:40:37.397573000][16][debug][client] [C2] response complete
envoy-proxy_1  | [2020-09-24 19:40:37.397938000][16][debug][pool] [C2] response complete
envoy-proxy_1  | [2020-09-24 19:40:37.397965000][16][debug][pool] [C2] destroying stream: 0 remaining
envoy-proxy_1  | [2020-09-24 19:40:37.400980000][16][debug][connection] [C0] remote close
envoy-proxy_1  | [2020-09-24 19:40:37.401012000][16][debug][connection] [C0] closing socket: 0
envoy-proxy_1  | [2020-09-24 19:40:37.401139000][16][debug][conn_handler] [C0] adding to cleanup list

cc @gsagula @dio
@brectanus-sigsci brectanus-sigsci added bug triage Issue requires triage labels Sep 24, 2020
@dio
Copy link
Member

dio commented Sep 24, 2020

@brectanus-sigsci thanks for reporting. Will take a look.

@mattklein123 mattklein123 added area/ext_authz help wanted Needs help! and removed triage Issue requires triage labels Sep 24, 2020
@dio dio mentioned this issue Sep 28, 2020
Merged
@dio
Copy link
Member

dio commented Sep 28, 2020

@brectanus-sigsci I have a PR here: #13288. And if you have time, could help to test it out? This is a ubuntu-based image containing that fix dio123/envoy:ext-authz-13260. Thank you!

@brectanus-sigsci
Copy link
Contributor Author

brectanus-sigsci commented Sep 29, 2020 •
edited
Loading

@dio I had a chance to look into this and test with dio123/envoy:ext-authz-13260, thanks!

[EDIT: Removed part of the example log below so that it showed only the same request as stated in the text.]

While this seems to fix the issue where I was seeing multiple calls, it also seems to cause another more serious issue where the request hangs (both downstream and upstream). It appears that once the body limit is reached it stops sending data to the upstream and does not finish the downstream request while the upstream waits endlessly for the request to finish sending the body. Normally canceling the downstream request clears this up, but if the downstream request is really big, then canceling the downstream does not seem to cancel the upstream and it hangs for some time (longer than I was willing to wait for it).

  • If I send under the body limit, then all goes through fine to the upstream and the downstream sends the response.
  • If I send over the body limit, then the HTTP client (curl in this case) hangs waiting for a response and does not return (assume it would eventually time out)
    • The upstream also seems to be waiting on more data to be sent in the body, so appears to hang
    • Canceling the curl request does not appear to trigger anything in envoy to cancel the request on very large files (here I get [debug][http] [C5][S10359588526714198394] Read-disabling downstream stream due to filter callbacks.)
    • When canceling the curl request does trigger in envoy, then it seems to cancel the request through to the upstream that gets an unexpected EOF having read only part of the body
    • When canceling curl does NOT trigger a cancel in envoy due to the large body, then shutting down envoy also does cause the transaction to get canceled and then the upstream gets an unexpected EOF having read partial body (but I am not seeing a timeout to trigger this - maybe it is just longer than I am waiting)

Here is an example request with curl with about 7MB body that hangs, then I wait a few seconds, then cancel the request (ctrl-C in curl). After canceling the upstream sees

# Upstream logs from
# curl -F file=@test-7mb.txt 'http://envoy-proxy/'
http-test-server_1          | POST / HTTP/1.1
http-test-server_1          | Host: envoy-proxy
http-test-server_1          | Accept: */*
http-test-server_1          | Content-Length: 6990699
http-test-server_1          | Content-Type: multipart/form-data; boundary=------------------------efbda755a5c1ff1d
http-test-server_1          | User-Agent: curl/7.71.1
http-test-server_1          | X-B3-Sampled: 0
http-test-server_1          | X-B3-Spanid: 3ce7bbe6710315cd
http-test-server_1          | X-B3-Traceid: 3ce7bbe6710315cd
http-test-server_1          | X-Envoy-Expected-Rq-Timeout-Ms: 15000
http-test-server_1          | X-Forwarded-Proto: http
http-test-server_1          | X-Request-Id: dd38de17-c26e-4673-a071-05bb8a5ce09b
http-test-server_1          |
http-test-server_1          | [discarded 1179648 bytes in 16.923540907s error="unexpected EOF"]

Here is the envoy debug log during the above request:

envoy-proxy_1  | [2020-09-29 14:41:25.184093261][16][debug][conn_handler] [C3] new connection
envoy-proxy_1  | [2020-09-29 14:41:25.184635609][16][debug][http] [C3] new stream
envoy-proxy_1  | [2020-09-29 14:41:25.184718825][16][debug][http] [C3][S4348318384577702094] request headers complete (end_stream=false):
envoy-proxy_1  | ':authority', 'envoy-proxy'
envoy-proxy_1  | ':path', '/'
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | 'user-agent', 'curl/7.71.1'
envoy-proxy_1  | 'accept', '*/*'
envoy-proxy_1  | 'content-length', '6990699'
envoy-proxy_1  | 'content-type', 'multipart/form-data; boundary=------------------------efbda755a5c1ff1d'
envoy-proxy_1  | 'expect', '100-continue'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:25.184780185][16][debug][filter] [C3][S4348318384577702094] ext_authz filter is buffering the request
envoy-proxy_1  | [2020-09-29 14:41:25.211651297][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.212642382][16][debug][router] [C0][S14285461520791920197] cluster 'my-grpc-cluster' match for URL '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | [2020-09-29 14:41:25.212708000][16][debug][router] [C0][S14285461520791920197] router decoding headers:
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | ':path', '/envoy.service.auth.v2.Authorization/Check'
envoy-proxy_1  | ':authority', 'my-grpc-cluster'
envoy-proxy_1  | ':scheme', 'http'
envoy-proxy_1  | 'te', 'trailers'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'x-b3-traceid', '3ce7bbe6710315cd'
envoy-proxy_1  | 'x-b3-spanid', '4b011d52ce7a73f3'
envoy-proxy_1  | 'x-b3-parentspanid', '3ce7bbe6710315cd'
envoy-proxy_1  | 'x-b3-sampled', '0'
envoy-proxy_1  | 'x-envoy-internal', 'true'
envoy-proxy_1  | 'x-forwarded-for', '172.18.0.4'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:25.212720252][16][debug][pool] [C1] using existing connection
envoy-proxy_1  | [2020-09-29 14:41:25.212725431][16][debug][pool] [C1] creating stream
envoy-proxy_1  | [2020-09-29 14:41:25.212735110][16][debug][router] [C0][S14285461520791920197] pool ready
envoy-proxy_1  | [2020-09-29 14:41:25.213407846][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.216263107][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.216429993][16][debug][router] [C0][S14285461520791920197] upstream headers complete: end_stream=false
envoy-proxy_1  | [2020-09-29 14:41:25.216516989][16][debug][http] async http request response headers (end_stream=false):
envoy-proxy_1  | ':status', '200'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'x-envoy-upstream-service-time', '3'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:25.216552739][16][debug][client] [C1] response complete
envoy-proxy_1  | [2020-09-29 14:41:25.216598435][16][debug][pool] [C1] destroying stream: 0 remaining
envoy-proxy_1  | [2020-09-29 14:41:25.216633807][16][debug][http] async http request response trailers:
envoy-proxy_1  | 'grpc-status', '0'
envoy-proxy_1  | 'grpc-message', ''
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:25.216686153][16][debug][router] [C3][S4348318384577702094] cluster 'http-test-server' match for URL '/'
envoy-proxy_1  | [2020-09-29 14:41:25.216739731][16][debug][router] [C3][S4348318384577702094] router decoding headers:
envoy-proxy_1  | ':authority', 'envoy-proxy'
envoy-proxy_1  | ':path', '/'
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | ':scheme', 'http'
envoy-proxy_1  | 'user-agent', 'curl/7.71.1'
envoy-proxy_1  | 'accept', '*/*'
envoy-proxy_1  | 'content-length', '6990699'
envoy-proxy_1  | 'content-type', 'multipart/form-data; boundary=------------------------efbda755a5c1ff1d'
envoy-proxy_1  | 'x-forwarded-proto', 'http'
envoy-proxy_1  | 'x-request-id', 'dd38de17-c26e-4673-a071-05bb8a5ce09b'
envoy-proxy_1  | 'x-envoy-expected-rq-timeout-ms', '15000'
envoy-proxy_1  | 'x-b3-traceid', '3ce7bbe6710315cd'
envoy-proxy_1  | 'x-b3-spanid', '3ce7bbe6710315cd'
envoy-proxy_1  | 'x-b3-sampled', '0'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:25.216765520][16][debug][pool] queueing stream due to no available connections
envoy-proxy_1  | [2020-09-29 14:41:25.216774882][16][debug][pool] creating a new connection
envoy-proxy_1  | [2020-09-29 14:41:25.216882773][16][debug][client] [C4] connecting
envoy-proxy_1  | [2020-09-29 14:41:25.216991723][16][debug][connection] [C4] connecting to 172.18.0.2:8801
envoy-proxy_1  | [2020-09-29 14:41:25.217244157][16][debug][connection] [C4] connection in progress
envoy-proxy_1  | [2020-09-29 14:41:25.217346017][16][debug][http2] [C1] stream closed: 0
envoy-proxy_1  | [2020-09-29 14:41:25.217494857][16][debug][connection] [C4] connected
envoy-proxy_1  | [2020-09-29 14:41:25.217534513][16][debug][client] [C4] connected
envoy-proxy_1  | [2020-09-29 14:41:25.217544552][16][debug][pool] [C4] attaching to next stream
envoy-proxy_1  | [2020-09-29 14:41:25.217552943][16][debug][pool] [C4] creating stream
envoy-proxy_1  | [2020-09-29 14:41:25.217568247][16][debug][router] [C3][S4348318384577702094] pool ready
envoy-proxy_1  | [2020-09-29 14:41:25.217596555][16][debug][http] [C3][S4348318384577702094] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-29 14:41:25.217642366][16][debug][http] [C3][S4348318384577702094] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-29 14:41:25.217660246][16][debug][connection] [C4] onAboveWriteBufferHighWatermark
envoy-proxy_1  | [2020-09-29 14:41:25.217666297][16][debug][http] [C3][S4348318384577702094] Read-disabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-29 14:41:25.219080611][16][debug][connection] [C4] onBelowWriteBufferLowWatermark
envoy-proxy_1  | [2020-09-29 14:41:25.219119973][16][debug][http] [C3][S4348318384577702094] Read-enabling downstream stream due to filter callbacks.
envoy-proxy_1  | [2020-09-29 14:41:25.247090735][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.248307265][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.248737365][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.249813210][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.250284120][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.251418388][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.252046243][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.253098621][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.253498147][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.255160663][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.256128713][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.257372801][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.258448550][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.258979545][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.260278167][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.260813964][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.261787769][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.262282587][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.263542618][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.264688328][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.265050983][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.266633353][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.267009735][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.268844239][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.270263714][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.270869371][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.272399737][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.272618019][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.273967056][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.274178761][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.276182600][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.277030169][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.278485837][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.279095253][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.281601252][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.281794623][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.283321039][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.283651537][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.284813878][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.286224234][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.287053159][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.288598416][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.289450299][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.290546531][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.290670797][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.291840162][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.292079209][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.293634853][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.294258813][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.297444342][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.297872431][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.299268312][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.299411253][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.300667971][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.300961544][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.302045402][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.302147873][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.303201134][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.303373043][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.304822546][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.305148980][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.307074971][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.307327869][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.309763317][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.309951727][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.311194660][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.312334746][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.312950244][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.315157716][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.316366180][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.317493432][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.318705780][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.319255584][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.321409559][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.322340237][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.323463195][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.324277735][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.325758788][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.327125195][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.327621568][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.329030226][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.329177699][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.330321453][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.330462226][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.332683295][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.332806371][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.334574691][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.335110200][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.336514441][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.337009818][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.338336762][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.339308650][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.339799847][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.340484477][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.341036525][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.342708300][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.344708906][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.344844701][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.346509058][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.346879386][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.348325177][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.348409767][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.350007237][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.350482052][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.352113392][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.352584468][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.354301867][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.355382737][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.355697993][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.356585829][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.356842425][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.358443424][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.359203022][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.360766943][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.361369351][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.362398583][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.363190591][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.364781541][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.365282748][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.366324103][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.367058980][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.368219283][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.369087228][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.370811270][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.372716873][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.374285906][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.376441286][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.377504917][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.378073103][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.379376738][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.379599699][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.380387133][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full
envoy-proxy_1  | [2020-09-29 14:41:25.380405306][16][debug][http] [C3][S4348318384577702094] request end stream
envoy-proxy_1  | [2020-09-29 14:41:25.380422519][16][debug][filter] [C3][S4348318384577702094] ext_authz filter finished buffering the request since buffer is full

[ curl hangs and I wait for curl to complete, then hit ctrl+C a few seconds later ]

envoy-proxy_1  | [2020-09-29 14:41:42.140608516][16][debug][connection] [C3] remote early close
envoy-proxy_1  | [2020-09-29 14:41:42.140667252][16][debug][connection] [C3] closing socket: 0
envoy-proxy_1  | [2020-09-29 14:41:42.140841265][16][debug][http] [C3][S4348318384577702094] stream reset
envoy-proxy_1  | [2020-09-29 14:41:42.141059820][16][debug][router] [C3][S4348318384577702094] resetting pool request
envoy-proxy_1  | [2020-09-29 14:41:42.141103109][16][debug][client] [C4] request reset
envoy-proxy_1  | [2020-09-29 14:41:42.141114426][16][debug][connection] [C4] closing data_to_write=0 type=1
envoy-proxy_1  | [2020-09-29 14:41:42.141118347][16][debug][connection] [C4] closing socket: 1
envoy-proxy_1  | [2020-09-29 14:41:42.141207083][16][debug][client] [C4] disconnect. resetting 0 pending requests
envoy-proxy_1  | [2020-09-29 14:41:42.141217765][16][debug][pool] [C4] client disconnected, failure reason: 
envoy-proxy_1  | [2020-09-29 14:41:42.141276436][16][debug][conn_handler] [C3] adding to cleanup list
envoy-proxy_1  | [2020-09-29 14:41:42.141295689][16][debug][pool] [C4] destroying stream: 0 remaining
envoy-proxy_1  | [2020-09-29 14:41:42.232476230][16][debug][router] [C0][S10467044651439557099] cluster 'my-grpc-cluster' match for URL '/envoy.service.accesslog.v2.AccessLogService/StreamAccessLogs'
envoy-proxy_1  | [2020-09-29 14:41:42.232548546][16][debug][router] [C0][S10467044651439557099] router decoding headers:
envoy-proxy_1  | ':method', 'POST'
envoy-proxy_1  | ':path', '/envoy.service.accesslog.v2.AccessLogService/StreamAccessLogs'
envoy-proxy_1  | ':authority', 'my-grpc-cluster'
envoy-proxy_1  | ':scheme', 'http'
envoy-proxy_1  | 'te', 'trailers'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 'x-envoy-internal', 'true'
envoy-proxy_1  | 'x-forwarded-for', '172.18.0.4'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:42.232561504][16][debug][pool] [C1] using existing connection
envoy-proxy_1  | [2020-09-29 14:41:42.232566187][16][debug][pool] [C1] creating stream
envoy-proxy_1  | [2020-09-29 14:41:42.232576871][16][debug][router] [C0][S10467044651439557099] pool ready
envoy-proxy_1  | [2020-09-29 14:41:42.233384276][16][debug][router] [C0][S10467044651439557099] upstream headers complete: end_stream=false
envoy-proxy_1  | [2020-09-29 14:41:42.233449464][16][debug][http] async http request response headers (end_stream=false):
envoy-proxy_1  | ':status', '200'
envoy-proxy_1  | 'content-type', 'application/grpc'
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:42.233481891][16][debug][client] [C1] response complete
envoy-proxy_1  | [2020-09-29 14:41:42.233497719][16][debug][pool] [C1] destroying stream: 0 remaining
envoy-proxy_1  | [2020-09-29 14:41:42.233508421][16][debug][router] [C0][S10467044651439557099] resetting pool request
envoy-proxy_1  | [2020-09-29 14:41:42.233517199][16][debug][http] async http request response trailers:
envoy-proxy_1  | 'grpc-status', '0'
envoy-proxy_1  | 'grpc-message', ''
envoy-proxy_1  | 
envoy-proxy_1  | [2020-09-29 14:41:42.233523580][16][debug][http2] [C1] stream closed: 0
envoy-proxy_1  | [2020-09-29 14:41:42.233530034][16][debug][http2] [C1] sent reset code=0

@brectanus-sigsci
Copy link
Contributor Author

@dio Sorry. I had paste in too much of the logs from a previous run above, so edited that comment to only show the content-length: 6990699 request in my example.

@dio
Copy link
Member

dio commented Sep 30, 2020

@brectanus-sigsci Thanks. Sorry for this 🤦🏽‍♂️, but I have an updated image here: dio123/envoy:ext-authz-13260-1. Thanks a lot for your time!

@brectanus-sigsci
Copy link
Contributor Author

Thanks @dio! This indeed seems to resolve the issue.

@dio
Copy link
Member

dio commented Sep 30, 2020

@brectanus-sigsci thank you! I attacked it wrongly, glad that it works now. cc. @junr03.

@mattklein123 mattklein123 added this to the 1.17.0 milestone Oct 11, 2020
lizan pushed a commit that referenced this issue Oct 16, 2020
@dio
ext_authz: Avoid calling check multiple times (#13288)
2196214 
This patch makes sure the filter sends exactly only one check request when the buffer is full, while there might be more data to be decoded.

Risk Level: Low
Testing: Unit test
Docs Changes: N/A
Release Notes: N/A
Fixes #13260

Signed-off-by: Dhi Aurrahman <dio@tetrate.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dio dio

Labels
area/ext_authz bug help wanted Needs help!
Projects
None yet
Milestone
1.17.0
Development

Successfully merging a pull request may close this issue.

ext_authz: Avoid calling check multiple times
3 participants
@dio @mattklein123 @brectanus-sigsci