ext_authz does not send Body in CheckRequest with HTTP2 #8666
Description
Title: ext_authz does not send Body in CheckRequest with HTTP2
Description:
Envoy version: v1.11.0
We are using the External Authorization plugin via GRPC (using envoy grpc service) for auth purposes. Our External Auth node needs sometimes to check the body in the request so we are sending it using the 'with_request_body' parameter in the plugin configuration. Unfortunatelly, the Body is not send in the CheckRequest message when using HTTP/2 protocol. Using HTTP/1.1 it works properly.
Repro steps:
Sending this curl operation reproduces the issue:
curl --http2-prior-knowledge -X POST 10.96.38.246:8080/endpoint -d ' { "field1" : "data1", "field2" : "data2", "field3" : [ "field3_1" ] } ' -H "Content-Type: application/json" -i
Config:
This is the configuration we are using related to the Ext Auth:
http_filters:
- name: envoy.ext_authz
config:
grpc_service:
envoy_grpc:
cluster_name: authz-cluster
timeout: 3s
clear_route_cache: true
status_on_error:
code: InternalServerError
with_request_body:
max_request_bytes: 2048
allow_partial_message: true
- name: envoy.router
Logs:
[2019-10-18 18:03:04.149][19][debug][main] [source/server/server.cc:170] flushing stats
[2019-10-18 18:03:05.627][19][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:89] starting async DNS resolution for localhost
[2019-10-18 18:03:05.627][19][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:96] async DNS resolution complete for localhost
[2019-10-18 18:03:05.627][19][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:89] starting async DNS resolution for localhost
[2019-10-18 18:03:05.627][19][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:96] async DNS resolution complete for localhost
[2019-10-18 18:03:08.668][28][debug][main] [source/server/connection_handler_impl.cc:280] [C18] new connection
[2019-10-18 18:03:08.668][28][trace][connection] [source/common/network/connection_impl.cc:456] [C18] socket event: 3
[2019-10-18 18:03:08.668][28][trace][connection] [source/common/network/connection_impl.cc:541] [C18] write ready
[2019-10-18 18:03:08.668][28][trace][connection] [source/common/network/connection_impl.cc:494] [C18] read ready
[2019-10-18 18:03:08.668][28][trace][connection] [source/common/network/raw_buffer_socket.cc:23] [C18] read returns: 357
[2019-10-18 18:03:08.668][28][trace][connection] [source/common/network/raw_buffer_socket.cc:37] [C18] read error: Resource temporarily unavailable
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: reset nghttp2_active_outbound_item
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: aob->item = (nil)
[2019-10-18 18:03:08.669][28][debug][http2] [source/common/http/http2/codec_impl.cc:726] [C18] setting stream-level initial window size to 268435456
[2019-10-18 18:03:08.669][28][debug][http2] [source/common/http/http2/codec_impl.cc:748] [C18] updating connection-level initial window size to 268435456
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/codec_impl.cc:343] [C18] dispatching 357 bytes
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: connection recv_window_size=0, local_window=268435456
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_FIRST_SETTINGS]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=18, type=4, flags=0x00, stream_id=0
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: SETTINGS
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_SETTINGS]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=6, payloadleft=12
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_SETTINGS]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=6, payloadleft=6
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_SETTINGS]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=6, payloadleft=0
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C18] recv frame type=4
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=4, type=8, flags=0x00, stream_id=0
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: WINDOW_UPDATE
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_NBYTE]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=4, payloadleft=0, left=0
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C18] recv frame type=8
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=88, type=1, flags=0x04, stream_id=1
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: HEADERS
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: no padding in payload
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: dep_add dep_stream(0x4068020)=0, stream(0x3d2d860)=1
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept closed streams num_closed_streams=0, num_incoming_streams=1, max_concurrent_streams=4294967295
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: call on_begin_headers callback stream_id=1
[2019-10-18 18:03:08.669][28][debug][http] [source/common/http/conn_manager_impl.cc:246] [C18] new stream
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEADER_BLOCK]
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=88, payloadleft=0
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: block final=1
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: decoding header block 88 bytes
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=1
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexed repr
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 3
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=3
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: :method: POST
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=1
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: literal header repr - indexed name
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexing required=0, no_index=0
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 4
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=4
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: huffman encoded=1
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 35
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: valuelen=35
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: 35 bytes read
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: :path: /endpoint
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=37
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.669][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexed repr
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 6
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=6
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: :scheme: http
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=1
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: literal header repr - indexed name
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexing required=1, no_index=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 1
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=1
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: huffman encoded=1
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 13
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: valuelen=13
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: 13 bytes read
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: :authority: 10.96.38.246:8080
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=15
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: literal header repr - indexed name
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexing required=1, no_index=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 58
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=58
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: huffman encoded=1
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 8
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: valuelen=8
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: 8 bytes read
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: user-agent: curl/7.58.0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=10
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: literal header repr - indexed name
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexing required=1, no_index=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 19
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=19
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: huffman encoded=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 3
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: valuelen=3
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: 3 bytes read
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: accept: */*
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=5
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: literal header repr - indexed name
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexing required=1, no_index=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 31
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=31
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: huffman encoded=1
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 11
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: valuelen=11
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: 11 bytes read
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: content-type: application/json
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=13
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: literal header repr - indexed name
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexing required=0, no_index=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 28
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=28
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: huffman encoded=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 3
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: valuelen=3
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: 3 bytes read
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: content-length: 187
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=6
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: all input bytes were processed
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: in_final set
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=0
[2019-10-18 18:03:08.670][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C18] recv frame type=1
[2019-10-18 18:03:08.671][28][debug][http] [source/common/http/conn_manager_impl.cc:600] [C18][S666307875404832439] request headers complete (end_stream=false):
':method', 'POST'
':path', '/endpoint'
':scheme', 'http'
':authority', '10.96.38.246:8080'
'user-agent', 'curl/7.58.0'
'accept', '*/*'
'content-type', 'application/json'
'content-length', '187'
[2019-10-18 18:03:08.671][28][debug][filter] [source/extensions/filters/http/ext_authz/ext_authz.cc:87] [C18][S666307875404832439] ext_authz filter is buffering the request
[2019-10-18 18:03:08.671][28][trace][http] [source/common/http/conn_manager_impl.cc:857] [C18][S666307875404832439] decode headers called: filter=0x409e820 status=1
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=187, type=0, flags=0x01, stream_id=1
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: DATA
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: no padding in payload
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_DATA]
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=187, payloadleft=0
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: data_readlen=187
[2019-10-18 18:03:08.671][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C18] recv frame type=0
[2019-10-18 18:03:08.671][28][debug][http] [source/common/http/conn_manager_impl.cc:1092] [C18][S666307875404832439] request end stream
[2019-10-18 18:03:08.671][28][debug][filter] [source/extensions/filters/http/ext_authz/ext_authz.cc:105] [C18][S666307875404832439] ext_authz filter finished buffering the request since stream is ended
[2019-10-18 18:03:08.672][28][trace][filter] [source/extensions/filters/http/ext_authz/ext_authz.cc:72] [C18][S666307875404832439] ext_authz filter calling authorization server
[2019-10-18 18:03:08.672][28][debug][router] [source/common/router/router.cc:401] [C0][S9232815829273650332] cluster 'authz-cluster' match for URL '/envoy.service.auth.v2.Authorization/Check'
[2019-10-18 18:03:08.673][28][debug][router] [source/common/router/router.cc:514] [C0][S9232815829273650332] router decoding headers:
':method', 'POST'
':path', '/envoy.service.auth.v2.Authorization/Check'
':authority', 'authz-cluster'
':scheme', 'http'
'te', 'trailers'
'grpc-timeout', '3000m'
'content-type', 'application/grpc'
'x-envoy-internal', 'true'
'x-forwarded-for', '192.168.0.43'
'x-envoy-expected-rq-timeout-ms', '3000'
[2019-10-18 18:03:08.673][28][debug][pool] [source/common/http/http2/conn_pool.cc:96] [C8] creating stream
[2019-10-18 18:03:08.674][28][debug][router] [source/common/router/router.cc:1503] [C0][S9232815829273650332] pool ready
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: dep_add dep_stream(0x4068a20)=0, stream(0x3d2d950)=3
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating :method: POST
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=2
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=2, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating :path: /envoy.service.auth.v2.Authorization/Check
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name match index=3
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indname index=3, valuelen=42, indexing_mode=1
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit string str=/envoy.service.auth.v2.Authorization/Check, length=42, huffman=1, encoded_length=30
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating :authority: udr-query-router
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=67
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=67, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating :scheme: http
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=5
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=5, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating te: trailers
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=66
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=66, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating grpc-timeout: 3000m
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=65
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=65, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating content-type: application/grpc
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=64
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=64, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating x-envoy-internal: true
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=63
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=63, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating x-forwarded-for: 192.168.0.43
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=62
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=62, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: deflating x-envoy-expected-rq-timeout-ms: 3000
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: name/value match index=61
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: emit indexed index=61, 1 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: deflatehd: all input name/value pairs were deflated
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: HEADERS/PUSH_PROMISE, payloadlen=41
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: before padding, HEADERS serialized in 50 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: padding selected: payloadlen=41, padlen=0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: padlen = 0, nothing to do
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: HEADERS finally serialized in 50 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: next frame: payloadlen=41, type=1, flags=0x04, stream_id=3
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: start transmitting frame type=1, length=50
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C8] send data: bytes=50
[2019-10-18 18:03:08.674][28][trace][connection] [source/common/network/connection_impl.cc:392] [C8] writing 50 bytes, end_stream false
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: end transmission of a frame
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C8] sent frame type=1
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: stream=3 attach item=0x40be140
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: stream=3 obq push cycle=0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: push stream 3 to stream 0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: reset nghttp2_active_outbound_item
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: aob->item = 0x40be0a0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: remote windowsize connection=4194304, remote maxframsize=4194304, stream(id 3)=4194304
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: available window=16384
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: DATA postponed due to Data transfer deferred
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: stream=3 defer item=0x40be140 cause=08
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: remove stream 3 from stream 0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: reset nghttp2_active_outbound_item
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: aob->item = (nil)
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: frame transmission deferred
[2019-10-18 18:03:08.674][28][trace][router] [source/common/router/router.cc:1403] [C0][S9232815829273650332] proxying 507 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: stream=3 resume item=0x40be140 flags=08
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: stream=3 obq push cycle=0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: push stream 3 to stream 0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: remote windowsize connection=4194304, remote maxframsize=4194304, stream(id 3)=4194304
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: available window=16384
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: padlen = 0, nothing to do
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: stream=3 obq resched cycle=8112
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: next frame: DATA
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: no copy DATA
[2019-10-18 18:03:08.674][28][trace][connection] [source/common/network/connection_impl.cc:392] [C8] writing 516 bytes, end_stream false
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: stream=3 detach item=0x40be140
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: remove stream 3 from stream 0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C8] sent frame type=0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: reset nghttp2_active_outbound_item
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: aob->item = 0x40be140
[2019-10-18 18:03:08.674][28][trace][http] [source/common/http/conn_manager_impl.cc:982] [C18][S666307875404832439] decode data called: filter=0x409e820 status=2
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/codec_impl.cc:358] [C18] dispatched 357 bytes
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: next frame: payloadlen=6, type=4, flags=0x00, stream_id=0
[2019-10-18 18:03:08.674][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: start transmitting frame type=4, length=15
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C18] send data: bytes=15
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/connection_impl.cc:392] [C18] writing 15 bytes, end_stream false
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: end transmission of a frame
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C18] sent frame type=4
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: reset nghttp2_active_outbound_item
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: aob->item = 0x3caef00
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: next frame: payloadlen=0, type=4, flags=0x01, stream_id=0
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: start transmitting frame type=4, length=9
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C18] send data: bytes=9
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/connection_impl.cc:392] [C18] writing 9 bytes, end_stream false
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: end transmission of a frame
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C18] sent frame type=4
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: reset nghttp2_active_outbound_item
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: aob->item = 0x40be3c0
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: next frame: payloadlen=4, type=8, flags=0x00, stream_id=0
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: start transmitting frame type=8, length=13
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C18] send data: bytes=13
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/connection_impl.cc:392] [C18] writing 13 bytes, end_stream false
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: end transmission of a frame
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C18] sent frame type=8
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: reset nghttp2_active_outbound_item
[2019-10-18 18:03:08.675][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: send: aob->item = 0x3caf7c0
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/connection_impl.cc:456] [C8] socket event: 2
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/connection_impl.cc:541] [C8] write ready
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/raw_buffer_socket.cc:66] [C8] write returns: 566
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/connection_impl.cc:456] [C18] socket event: 2
[2019-10-18 18:03:08.675][28][trace][connection] [source/common/network/connection_impl.cc:541] [C18] write ready
[2019-10-18 18:03:08.676][28][trace][connection] [source/common/network/raw_buffer_socket.cc:66] [C18] write returns: 37
[2019-10-18 18:03:08.676][28][trace][connection] [source/common/network/connection_impl.cc:456] [C18] socket event: 3
[2019-10-18 18:03:08.676][28][trace][connection] [source/common/network/connection_impl.cc:541] [C18] write ready
[2019-10-18 18:03:08.676][28][trace][connection] [source/common/network/connection_impl.cc:494] [C18] read ready
[2019-10-18 18:03:08.676][28][trace][connection] [source/common/network/raw_buffer_socket.cc:23] [C18] read returns: 9
[2019-10-18 18:03:08.676][28][trace][connection] [source/common/network/raw_buffer_socket.cc:37] [C18] read error: Resource temporarily unavailable
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/codec_impl.cc:343] [C18] dispatching 9 bytes
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: connection recv_window_size=187, local_window=268435456
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=0, type=4, flags=0x01, stream_id=0
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: SETTINGS
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_SETTINGS]
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=0, payloadleft=0
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C18] recv frame type=4
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/codec_impl.cc:358] [C18] dispatched 9 bytes
[2019-10-18 18:03:08.676][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.678][28][trace][connection] [source/common/network/connection_impl.cc:456] [C8] socket event: 3
[2019-10-18 18:03:08.678][28][trace][connection] [source/common/network/connection_impl.cc:541] [C8] write ready
[2019-10-18 18:03:08.679][28][trace][connection] [source/common/network/connection_impl.cc:494] [C8] read ready
[2019-10-18 18:03:08.679][28][trace][connection] [source/common/network/raw_buffer_socket.cc:23] [C8] read returns: 151
[2019-10-18 18:03:08.679][28][trace][connection] [source/common/network/raw_buffer_socket.cc:37] [C8] read error: Resource temporarily unavailable
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/codec_impl.cc:343] [C8] dispatching 151 bytes
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: connection recv_window_size=89, local_window=268435456
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: stream: adjusting kept idle streams num_idle_streams=0, max=100
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=4, type=1, flags=0x04, stream_id=3
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: HEADERS
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: no padding in payload
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: call on_begin_headers callback stream_id=3
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEADER_BLOCK]
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=4, payloadleft=0
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: block final=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: decoding header block 4 bytes
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexed repr
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 8
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=8
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: :status: 200
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexed repr
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 65
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=65
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: content-type: application/grpc
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexed repr
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 64
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=64
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: grpc-accept-encoding: identity,deflate,gzip
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexed repr
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 63
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=63
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: accept-encoding: identity,gzip
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: all input bytes were processed
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: in_final set
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=0
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C8] recv frame type=1
[2019-10-18 18:03:08.679][28][debug][router] [source/common/router/router.cc:994] [C0][S9232815829273650332] upstream headers complete: end_stream=false
[2019-10-18 18:03:08.679][28][debug][http] [source/common/http/async_client_impl.cc:91] async http request response headers (end_stream=false):
':status', '200'
'content-type', 'application/grpc'
'grpc-accept-encoding', 'identity,deflate,gzip'
'accept-encoding', 'identity,gzip'
'x-envoy-upstream-service-time', '4'
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=89, type=0, flags=0x00, stream_id=3
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: DATA
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: no padding in payload
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_DATA]
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=89, payloadleft=0
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: data_readlen=89
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C8] recv frame type=0
[2019-10-18 18:03:08.679][28][trace][http] [source/common/http/async_client_impl.cc:99] async http request response data (length=89 end_stream=false)
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEAD]
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: payloadlen=1, type=1, flags=0x05, stream_id=3
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: HEADERS
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: no padding in payload
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: call on_begin_headers callback stream_id=3
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: [IB_READ_HEADER_BLOCK]
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: readlen=1, payloadleft=0
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: block final=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: decoding header block 1 bytes
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: indexed repr
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: decoded integer is 62
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: index=62
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: header emission: grpc-status: 0
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=1
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: start state=2
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: all input bytes were processed
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: inflatehd: in_final set
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/nghttp2.cc:20] nghttp2: recv: proclen=0
[2019-10-18 18:03:08.679][28][trace][http2] [source/common/http/http2/codec_impl.cc:401] [C8] recv frame type=1
[2019-10-18 18:03:08.679][28][debug][client] [source/common/http/codec_client.cc:95] [C8] response complete
[2019-10-18 18:03:08.679][28][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=1)
[2019-10-18 18:03:08.679][28][debug][pool] [source/common/http/http2/conn_pool.cc:233] [C8] destroying stream: 0 remaining
[2019-10-18 18:03:08.679][28][debug][http] [source/common/http/async_client_impl.cc:106] async http request response trailers:
'grpc-status', '0'
[2019-10-18 18:03:08.680][28][trace][filter] [source/extensions/filters/http/ext_authz/ext_authz.cc:150] [C18][S666307875404832439] ext_authz filter added header(s) to the request:
[2019-10-18 18:03:08.680][28][debug][filter] [source/extensions/filters/http/ext_authz/ext_authz.cc:153] [C18][S666307875404832439] ext_authz is clearing route cache
[2019-10-18 18:03:08.680][28][trace][http] [source/common/http/conn_manager_impl.cc:1673] [C18][S666307875404832439] continuing filter chain: filter=0x409e820
[2019-10-18 18:03:08.680][28][debug][router] [source/common/router/router.cc:401] [C18][S666307875404832439] cluster 'local' match for URL '/endpoint'
[2019-10-18 18:03:08.680][28][debug][router] [source/common/router/router.cc:514] [C18][S666307875404832439] router decoding headers:
':method', 'POST'
':path', '/endpoint'
':scheme', 'http'
':authority', '10.96.38.246:8080'
'user-agent', 'curl/7.58.0'
'accept', '*/*'
'content-type', 'application/json'
'content-length', '187'
'x-forwarded-proto', 'http'
'x-request-id', 'ede00eed-a8aa-4c59-87db-74b7274dfdfd'
'x-envoy-expected-rq-timeout-ms', '15000'
I modified the code a little (hope I did it in the proper place) to log what is the body received when creating the HTTP Request and it says the buffer is null when it should not (file check_request_utils.cc, method CheckRequestUtils::setHttpRequest):
void CheckRequestUtils::setHttpRequest(
::envoy::service::auth::v2::AttributeContext_HttpRequest& httpreq,
const Envoy::Http::StreamDecoderFilterCallbacks* callbacks,
const Envoy::Http::HeaderMap& headers, uint64_t max_request_bytes) {
[...]
// Set request body.
std::cout << "MYLOG: set request body" << std::endl;
const Buffer::Instance* buffer = sdfc->decodingBuffer();
if (max_request_bytes > 0 && buffer != nullptr) {
const uint64_t length = std::min(buffer->length(), max_request_bytes);
std::string data(length, 0);
buffer->copyOut(0, length, &data[0]);
std::cout << "DATA: " << data << << std::endl;
httpreq.set_body(std::move(data));
// Add in a header to detect when a partial body is used.
(*mutable_headers)[Http::Headers::get().EnvoyAuthPartialBody.get()] =
length != buffer->length() ? "true" : "false";
} else {
if (buffer == nullptr) {
std::cout << "MYLOG: buffer is null" << std::endl;
}
}
}
The result of the curl operation prints out this:
MYLOG: set request body
MYLOG: buffer is null
But executing with HTTP1.1:
MYLOG: set request body
DATA: { "field1" : "data1", "field2" : "data2", "field3" : [ "field3_1" ] }
Hope this helps.
Thanks a lot for your great product!
\Mariano.