Envoy: http2 to external upstream fails

Created on 14 Aug 2019 · 3Comments · Source: envoyproxy/envoy

Description

I'm attempting to setup an envoy that provides egress to an HTTP2 enabled server and consistently see 503 responses saying connection terminated. Switching to HTTP/1.1 on the upstream works just fine. I've simplified my configuration to use an example server, but any h2 server seems to behave the same.

I'm new to envoy, so I'm sure I'm doing something wrong here, but I've tried every combination of configuration I can think of. Any help would be appreciated. Thanks!

Repro steps

1) save config below as envoy.yaml

2) see successful request via HTTP/1.1 to upstream

[term 1]
$ docker run -it -p 8080:8080 --mount "type=bind,source=$(pwd)/envoy.yaml,target=/etc/envoy/envoy.yaml" envoyproxy/envoy:v1.11.0 -c /etc/envoy/envoy.yaml -l trace`

[term 2]
$ curl -v http://localhost:8080/reqinfo
HTTP/1.1 200 OK
[... rest of successful response ...]

3) uncomment http2_protocol_options in config and restart docker instance

$ curl -i http://localhost:8080/reqinfo
HTTP/1.1 503 Service Unavailable
content-length: 95
content-type: text/plain
date: Wed, 14 Aug 2019 20:57:18 GMT
server: envoy

upstream connect error or disconnect/reset before headers. reset reason: connection termination

Config

```static_resources:
listeners:

address:
socket_address:
address: 0.0.0.0
port_value: 8080
filter_chains:
- filters:
  - name: envoy.http_connection_manager
    
    config:
    
    stat_prefix: ingress_http
    
    route_config:
    
    name: local_route
    
    virtual_hosts:
    - name: backend
      
      domains: ["*"]
      
      routes:
      - match:
        
        prefix: /
        
        route:
        
        cluster: upstream
        
        auto_host_rewrite: true
        
        http_filters:
    - name: envoy.router
      
      clusters:
name: upstream
connect_timeout: 1s
type: strict_dns
lb_policy: round_robin
# http2_protocol_options: {} ## UNCOMMENT ME FOR TROUBLE
respect_dns_ttl: true
tls_context:
sni: http2.golang.org
load_assignment:
cluster_name: upstream
endpoints:
- lb_endpoints:
  - endpoint:
    
    address:
    
    socket_address:
    
    address: http2.golang.org
    
    port_value: 443
    
    protocol: TCP


### Logs

[2019-08-14 20:57:16.290][1][info][main] [source/server/server.cc:238] initializing epoch 0 (hot restart version=11.104)
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:240] statically linked extensions:
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:242] access_loggers: envoy.file_access_log,envoy.http_grpc_access_log
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:245] filters.http: envoy.buffer,envoy.cors,envoy.csrf,envoy.ext_authz,envoy.fault,envoy.filters.http.dynamic_forward_proxy,envoy.filters.http.grpc_http1_reverse_bridge,envoy.filters.http.header_to_metadata,envoy.filters.http.jwt_authn,envoy.filters.http.original_src,envoy.filters.http.rbac,envoy.filters.http.tap,envoy.grpc_http1_bridge,envoy.grpc_json_transcoder,envoy.grpc_web,envoy.gzip,envoy.health_check,envoy.http_dynamo_filter,envoy.ip_tagging,envoy.lua,envoy.rate_limit,envoy.router,envoy.squash
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:248] filters.listener: envoy.listener.original_dst,envoy.listener.original_src,envoy.listener.proxy_protocol,envoy.listener.tls_inspector
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:251] filters.network: envoy.client_ssl_auth,envoy.echo,envoy.ext_authz,envoy.filters.network.dubbo_proxy,envoy.filters.network.mysql_proxy,envoy.filters.network.rbac,envoy.filters.network.sni_cluster,envoy.filters.network.thrift_proxy,envoy.filters.network.zookeeper_proxy,envoy.http_connection_manager,envoy.mongo_proxy,envoy.ratelimit,envoy.redis_proxy,envoy.tcp_proxy
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:253] stat_sinks: envoy.dog_statsd,envoy.metrics_service,envoy.stat_sinks.hystrix,envoy.statsd
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:255] tracers: envoy.dynamic.ot,envoy.lightstep,envoy.tracers.datadog,envoy.tracers.opencensus,envoy.zipkin
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:258] transport_sockets.downstream: envoy.transport_sockets.alts,envoy.transport_sockets.tap,raw_buffer,tls
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:261] transport_sockets.upstream: envoy.transport_sockets.alts,envoy.transport_sockets.tap,raw_buffer,tls
[2019-08-14 20:57:16.291][1][info][main] [source/server/server.cc:267] buffer implementation: old (libevent)
[2019-08-14 20:57:16.304][1][warning][main] [source/server/server.cc:327] No admin address given, so no admin HTTP server started.
[2019-08-14 20:57:16.304][1][debug][main] [source/server/overload_manager_impl.cc:173] No overload action is configured for envoy.overload_actions.shrink_heap.
[2019-08-14 20:57:16.304][1][debug][main] [source/server/overload_manager_impl.cc:173] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
[2019-08-14 20:57:16.304][1][debug][main] [source/server/overload_manager_impl.cc:173] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
[2019-08-14 20:57:16.304][1][debug][main] [source/server/overload_manager_impl.cc:173] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
[2019-08-14 20:57:16.304][1][debug][main] [source/server/overload_manager_impl.cc:173] No overload action is configured for envoy.overload_actions.stop_accepting_connections.
[2019-08-14 20:57:16.305][1][info][main] [source/server/server.cc:432] runtime: layers:

name: base
static_layer:
{}
name: admin
admin_layer:
{}
[2019-08-14 20:57:16.305][1][warning][runtime] [source/common/runtime/runtime_impl.cc:485] Skipping unsupported runtime layer: name: "base"
static_layer {
}

[2019-08-14 20:57:16.305][1][info][config] [source/server/configuration_impl.cc:61] loading 0 static secret(s)
[2019-08-14 20:57:16.305][1][info][config] [source/server/configuration_impl.cc:67] loading 1 cluster(s)
[2019-08-14 20:57:16.305][9][debug][grpc] [source/common/grpc/google_async_client_impl.cc:43] completionThread running
[2019-08-14 20:57:16.306][1][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:839] adding TLS initial cluster upstream
[2019-08-14 20:57:16.307][1][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:89] starting async DNS resolution for http2.golang.org
[2019-08-14 20:57:16.307][1][trace][upstream] [source/common/network/dns_impl.cc:160] Setting DNS resolution timer for 5000 milliseconds
[2019-08-14 20:57:16.307][1][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:75] cm init: adding: cluster=upstream primary=1 secondary=0
[2019-08-14 20:57:16.307][1][info][config] [source/server/configuration_impl.cc:71] loading 1 listener(s)
[2019-08-14 20:57:16.307][1][debug][config] [source/server/configuration_impl.cc:73] listener #0:
[2019-08-14 20:57:16.307][1][debug][config] [source/server/listener_manager_impl.cc:485] begin add/update listener: name=c17fb16f-0576-4d4c-a3b3-e159ac47a836 hash=3421765951345632697
[2019-08-14 20:57:16.308][1][debug][config] [source/server/listener_manager_impl.cc:57] filter #0:
[2019-08-14 20:57:16.308][1][debug][config] [source/server/listener_manager_impl.cc:58] name: envoy.http_connection_manager
[2019-08-14 20:57:16.308][1][debug][config] [source/server/listener_manager_impl.cc:61] config: {"route_config":{"virtual_hosts":[{"name":"backend","routes":[{"match":{"prefix":"/"},"route":{"auto_host_rewrite":true,"cluster":"upstream"}}],"domains":[""]}],"name":"local_route"},"http_filters":[{"name":"envoy.router"}],"stat_prefix":"ingress_http"}
[2019-08-14 20:57:16.310][1][debug][config] [source/extensions/filters/network/http_connection_manager/config.cc:340] http filter #0
[2019-08-14 20:57:16.310][1][debug][config] [source/extensions/filters/network/http_connection_manager/config.cc:341] name: envoy.router
[2019-08-14 20:57:16.310][1][debug][config] [source/extensions/filters/network/http_connection_manager/config.cc:345] config: {}
[2019-08-14 20:57:16.310][1][debug][config] [source/server/listener_manager_impl.cc:376] add active listener: name=c17fb16f-0576-4d4c-a3b3-e159ac47a836, hash=3421765951345632697, address=0.0.0.0:8080
[2019-08-14 20:57:16.310][1][info][config] [source/server/configuration_impl.cc:96] loading tracing configuration
[2019-08-14 20:57:16.310][1][info][config] [source/server/configuration_impl.cc:116] loading stats sink configuration
[2019-08-14 20:57:16.311][1][info][main] [source/server/server.cc:516] starting main dispatch loop
[2019-08-14 20:57:16.327][1][trace][upstream] [source/common/network/dns_impl.cc:160] Setting DNS resolution timer for 5000 milliseconds
[2019-08-14 20:57:16.329][1][trace][upstream] [source/common/upstream/strict_dns_cluster.cc:96] async DNS resolution complete for http2.golang.org
[2019-08-14 20:57:16.329][1][debug][upstream] [source/common/upstream/strict_dns_cluster.cc:122] DNS hosts have changed for http2.golang.org
[2019-08-14 20:57:16.329][1][trace][upstream] [source/common/upstream/upstream_impl.cc:1001] Local locality:
[2019-08-14 20:57:16.329][1][debug][upstream] [source/common/upstream/upstream_impl.cc:773] initializing secondary cluster upstream completed
[2019-08-14 20:57:16.329][1][debug][init] [source/common/init/manager_impl.cc:45] init manager Cluster upstream contains no targets
[2019-08-14 20:57:16.329][1][debug][init] [source/common/init/watcher_impl.cc:14] init manager Cluster upstream initialized, notifying ClusterImplBase
[2019-08-14 20:57:16.329][1][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:999] membership update for TLS cluster upstream added 1 removed 0
[2019-08-14 20:57:16.329][1][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:103] cm init: init complete: cluster=upstream primary=0 secondary=0
[2019-08-14 20:57:16.329][1][info][upstream] [source/common/upstream/cluster_manager_impl.cc:148] cm init: all clusters initialized
[2019-08-14 20:57:16.329][1][info][main] [source/server/server.cc:500] all clusters initialized. initializing init manager
[2019-08-14 20:57:16.329][1][debug][init] [source/common/init/manager_impl.cc:45] init manager Server contains no targets
[2019-08-14 20:57:16.329][1][debug][init] [source/common/init/watcher_impl.cc:14] init manager Server initialized, notifying RunHelper
[2019-08-14 20:57:16.329][1][info][config] [source/server/listener_manager_impl.cc:761] all dependencies initialized. starting workers
[2019-08-14 20:57:16.330][11][debug][main] [source/server/worker_impl.cc:101] worker entering dispatch loop
[2019-08-14 20:57:16.330][12][debug][main] [source/server/worker_impl.cc:101] worker entering dispatch loop
[2019-08-14 20:57:16.330][13][debug][main] [source/server/worker_impl.cc:101] worker entering dispatch loop
[2019-08-14 20:57:16.331][11][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:839] adding TLS initial cluster upstream
[2019-08-14 20:57:16.331][14][debug][grpc] [source/common/grpc/google_async_client_impl.cc:43] completionThread running
[2019-08-14 20:57:16.331][15][debug][main] [source/server/worker_impl.cc:101] worker entering dispatch loop
[2019-08-14 20:57:16.331][1][debug][upstream] [source/common/upstream/strict_dns_cluster.cc:144] DNS refresh rate reset for http2.golang.org, refresh rate 4502000 ms
[2019-08-14 20:57:16.331][11][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:999] membership update for TLS cluster upstream added 1 removed 0
[2019-08-14 20:57:16.331][12][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:839] adding TLS initial cluster upstream
[2019-08-14 20:57:16.331][16][debug][grpc] [source/common/grpc/google_async_client_impl.cc:43] completionThread running
[2019-08-14 20:57:16.332][15][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:839] adding TLS initial cluster upstream
[2019-08-14 20:57:16.332][17][debug][grpc] [source/common/grpc/google_async_client_impl.cc:43] completionThread running
[2019-08-14 20:57:16.332][12][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:999] membership update for TLS cluster upstream added 1 removed 0
[2019-08-14 20:57:16.333][15][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:999] membership update for TLS cluster upstream added 1 removed 0
[2019-08-14 20:57:16.333][13][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:839] adding TLS initial cluster upstream
[2019-08-14 20:57:16.333][13][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:999] membership update for TLS cluster upstream added 1 removed 0
[2019-08-14 20:57:16.333][18][debug][grpc] [source/common/grpc/google_async_client_impl.cc:43] completionThread running
[2019-08-14 20:57:18.471][15][debug][main] [source/server/connection_handler_impl.cc:280] [C0] new connection
[2019-08-14 20:57:18.471][15][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 2
[2019-08-14 20:57:18.471][15][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-14 20:57:18.471][15][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 3
[2019-08-14 20:57:18.471][15][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-14 20:57:18.471][15][trace][connection] [source/common/network/connection_impl.cc:494] [C0] read ready
[2019-08-14 20:57:18.472][15][trace][connection] [source/common/network/raw_buffer_socket.cc:23] [C0] read returns: 85
[2019-08-14 20:57:18.472][15][trace][connection] [source/common/network/raw_buffer_socket.cc:37] [C0] read error: Resource temporarily unavailable
[2019-08-14 20:57:18.472][15][trace][http] [source/common/http/http1/codec_impl.cc:366] [C0] parsing 85 bytes
[2019-08-14 20:57:18.472][15][trace][http] [source/common/http/http1/codec_impl.cc:479] [C0] message begin
[2019-08-14 20:57:18.472][15][debug][http] [source/common/http/conn_manager_impl.cc:246] [C0] new stream
[2019-08-14 20:57:18.472][15][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=Host value=localhost:8080
[2019-08-14 20:57:18.473][15][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=User-Agent value=curl/7.54.0
[2019-08-14 20:57:18.473][15][trace][http] [source/common/http/http1/codec_impl.cc:445] [C0] headers complete
[2019-08-14 20:57:18.473][15][trace][http] [source/common/http/http1/codec_impl.cc:334] [C0] completed header: key=Accept value=/*
[2019-08-14 20:57:18.473][15][trace][http] [source/common/http/http1/codec_impl.cc:466] [C0] message complete
[2019-08-14 20:57:18.473][15][debug][http] [source/common/http/conn_manager_impl.cc:600] [C0][S3890394461460335529] request headers complete (end_stream=true):
':authority', 'localhost:8080'
':path', '/reqinfo'
':method', 'GET'
'user-agent', 'curl/7.54.0'
'accept', '/'

[2019-08-14 20:57:18.473][15][debug][http] [source/common/http/conn_manager_impl.cc:1092] [C0][S3890394461460335529] request end stream
[2019-08-14 20:57:18.474][15][debug][router] [source/common/router/router.cc:401] [C0][S3890394461460335529] cluster 'upstream' match for URL '/reqinfo'
[2019-08-14 20:57:18.474][15][debug][router] [source/common/router/router.cc:514] [C0][S3890394461460335529] router decoding headers:
':authority', 'localhost:8080'
':path', '/reqinfo'
':method', 'GET'
':scheme', 'https'
'user-agent', 'curl/7.54.0'
'accept', '/'
'x-forwarded-proto', 'http'
'x-request-id', '515e2ccc-4617-4fce-9d9d-4418921606f4'
'x-envoy-expected-rq-timeout-ms', '15000'

[2019-08-14 20:57:18.474][15][debug][client] [source/common/http/codec_client.cc:26] [C1] connecting
[2019-08-14 20:57:18.474][15][debug][connection] [source/common/network/connection_impl.cc:702] [C1] connecting to 130.211.116.44:443
[2019-08-14 20:57:18.474][15][debug][connection] [source/common/network/connection_impl.cc:711] [C1] connection in progress
[2019-08-14 20:57:18.475][15][debug][http2] [source/common/http/http2/codec_impl.cc:726] [C1] setting stream-level initial window size to 268435456
[2019-08-14 20:57:18.475][15][debug][http2] [source/common/http/http2/codec_impl.cc:748] [C1] updating connection-level initial window size to 268435456
[2019-08-14 20:57:18.475][15][debug][pool] [source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2019-08-14 20:57:18.475][15][trace][http] [source/common/http/conn_manager_impl.cc:857] [C0][S3890394461460335529] decode headers called: filter=0x24aa730 status=1
[2019-08-14 20:57:18.475][15][trace][http] [source/common/http/http1/codec_impl.cc:387] [C0] parsed 85 bytes
[2019-08-14 20:57:18.475][15][trace][connection] [source/common/network/connection_impl.cc:288] [C0] readDisable: enabled=true disable=true
[2019-08-14 20:57:18.475][15][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 2
[2019-08-14 20:57:18.475][15][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-14 20:57:18.524][15][trace][connection] [source/common/network/connection_impl.cc:456] [C1] socket event: 2
[2019-08-14 20:57:18.524][15][trace][connection] [source/common/network/connection_impl.cc:541] [C1] write ready
[2019-08-14 20:57:18.524][15][debug][connection] [source/common/network/connection_impl.cc:550] [C1] connected
[2019-08-14 20:57:18.524][15][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:168] [C1] handshake error: 2
[2019-08-14 20:57:18.572][15][trace][connection] [source/common/network/connection_impl.cc:456] [C1] socket event: 3
[2019-08-14 20:57:18.572][15][trace][connection] [source/common/network/connection_impl.cc:541] [C1] write ready
[2019-08-14 20:57:18.574][15][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:168] [C1] handshake error: 2
[2019-08-14 20:57:18.574][15][trace][connection] [source/common/network/connection_impl.cc:494] [C1] read ready
[2019-08-14 20:57:18.574][15][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:168] [C1] handshake error: 2
[2019-08-14 20:57:18.622][15][trace][connection] [source/common/network/connection_impl.cc:456] [C1] socket event: 3
[2019-08-14 20:57:18.622][15][trace][connection] [source/common/network/connection_impl.cc:541] [C1] write ready
[2019-08-14 20:57:18.622][15][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:157] [C1] handshake complete
[2019-08-14 20:57:18.623][15][debug][client] [source/common/http/codec_client.cc:64] [C1] connected
[2019-08-14 20:57:18.623][15][debug][pool] [source/common/http/http2/conn_pool.cc:96] [C1] creating stream
[2019-08-14 20:57:18.623][15][debug][router] [source/common/router/router.cc:1503] [C0][S3890394461460335529] pool ready
[2019-08-14 20:57:18.623][15][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C1] send data: bytes=24
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:392] [C1] writing 24 bytes, end_stream false
[2019-08-14 20:57:18.623][15][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C1] send data: bytes=21
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:392] [C1] writing 21 bytes, end_stream false
[2019-08-14 20:57:18.623][15][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C1] sent frame type=4
[2019-08-14 20:57:18.623][15][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C1] send data: bytes=13
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:392] [C1] writing 13 bytes, end_stream false
[2019-08-14 20:57:18.623][15][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C1] sent frame type=8
[2019-08-14 20:57:18.623][15][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C1] send data: bytes=134
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:392] [C1] writing 134 bytes, end_stream false
[2019-08-14 20:57:18.623][15][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C1] sent frame type=1
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:541] [C1] write ready
[2019-08-14 20:57:18.623][15][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:234] [C1] ssl write returns: 192
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:494] [C1] read ready
[2019-08-14 20:57:18.623][15][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:73] [C1] ssl read returns: -1
[2019-08-14 20:57:18.623][15][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:148] [C1] ssl read 0 bytes into 0 slices
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:456] [C1] socket event: 2
[2019-08-14 20:57:18.623][15][trace][connection] [source/common/network/connection_impl.cc:541] [C1] write ready
[2019-08-14 20:57:18.671][15][trace][connection] [source/common/network/connection_impl.cc:456] [C1] socket event: 3
[2019-08-14 20:57:18.672][15][trace][connection] [source/common/network/connection_impl.cc:541] [C1] write ready
[2019-08-14 20:57:18.672][15][trace][connection] [source/common/network/connection_impl.cc:494] [C1] read ready
[2019-08-14 20:57:18.672][15][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:73] [C1] ssl read returns: 103
[2019-08-14 20:57:18.672][15][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:73] [C1] ssl read returns: 0
[2019-08-14 20:57:18.672][15][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:148] [C1] ssl read 103 bytes into 1 slices
[2019-08-14 20:57:18.672][15][trace][http2] [source/common/http/http2/codec_impl.cc:343] [C1] dispatching 103 bytes
[2019-08-14 20:57:18.672][15][trace][http2] [source/common/http/http2/codec_impl.cc:358] [C1] dispatched 103 bytes
[2019-08-14 20:57:18.672][15][trace][http2] [source/common/http/http2/codec_impl.cc:559] [C1] send data: bytes=34
[2019-08-14 20:57:18.672][15][trace][connection] [source/common/network/connection_impl.cc:392] [C1] writing 34 bytes, end_stream false
[2019-08-14 20:57:18.672][15][trace][http2] [source/common/http/http2/codec_impl.cc:511] [C1] sent frame type=7
[2019-08-14 20:57:18.672][15][debug][http2] [source/common/http/http2/codec_impl.cc:514] [C1] sent goaway code=1
[2019-08-14 20:57:18.672][15][debug][client] [source/common/http/codec_client.cc:118] [C1] protocol error: The user callback function failed
[2019-08-14 20:57:18.672][15][debug][connection] [source/common/network/connection_impl.cc:101] [C1] closing data_to_write=34 type=1
[2019-08-14 20:57:18.672][15][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:234] [C1] ssl write returns: 34
[2019-08-14 20:57:18.672][15][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:270] [C1] SSL shutdown: rc=1
[2019-08-14 20:57:18.672][15][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:201] [C1]
[2019-08-14 20:57:18.672][15][debug][connection] [source/common/network/connection_impl.cc:188] [C1] closing socket: 1
[2019-08-14 20:57:18.672][15][debug][client] [source/common/http/codec_client.cc:82] [C1] disconnect. resetting 1 pending requests
[2019-08-14 20:57:18.673][15][debug][client] [source/common/http/codec_client.cc:105] [C1] request reset
[2019-08-14 20:57:18.673][15][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=1)
[2019-08-14 20:57:18.673][15][debug][pool] [source/common/http/http2/conn_pool.cc:233] [C1] destroying stream: 0 remaining
[2019-08-14 20:57:18.673][15][debug][router] [source/common/router/router.cc:868] [C0][S3890394461460335529] upstream reset: reset reason connection termination
[2019-08-14 20:57:18.673][15][debug][http] [source/common/http/conn_manager_impl.cc:1167] [C0][S3890394461460335529] Sending local reply with details upstream_reset_before_response_started{connection termination}
[2019-08-14 20:57:18.673][15][debug][http] [source/common/http/conn_manager_impl.cc:1359] [C0][S3890394461460335529] encoding headers via codec (end_stream=false):
':status', '503'
'content-length', '95'
'content-type', 'text/plain'
'date', 'Wed, 14 Aug 2019 20:57:18 GMT'
'server', 'envoy'

[2019-08-14 20:57:18.673][15][trace][connection] [source/common/network/connection_impl.cc:392] [C0] writing 134 bytes, end_stream false
[2019-08-14 20:57:18.673][15][trace][http] [source/common/http/conn_manager_impl.cc:1497] [C0][S3890394461460335529] encoding data via codec (size=95 end_stream=true)
[2019-08-14 20:57:18.673][15][trace][connection] [source/common/network/connection_impl.cc:392] [C0] writing 95 bytes, end_stream false
[2019-08-14 20:57:18.673][15][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=2)
[2019-08-14 20:57:18.673][15][trace][connection] [source/common/network/connection_impl.cc:288] [C0] readDisable: enabled=false disable=false
[2019-08-14 20:57:18.673][15][debug][pool] [source/common/http/http2/conn_pool.cc:149] [C1] client disconnected
[2019-08-14 20:57:18.673][15][debug][pool] [source/common/http/http2/conn_pool.cc:171] [C1] destroying primary client
[2019-08-14 20:57:18.673][15][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=3)
[2019-08-14 20:57:18.673][15][debug][connection] [source/common/network/connection_impl.cc:518] [C1] remote close
[2019-08-14 20:57:18.673][15][trace][main] [source/common/event/dispatcher_impl.cc:76] clearing deferred deletion list (size=3)
[2019-08-14 20:57:18.673][15][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 2
[2019-08-14 20:57:18.673][15][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-14 20:57:18.673][15][trace][connection] [source/common/network/raw_buffer_socket.cc:66] [C0] write returns: 229
[2019-08-14 20:57:18.675][15][trace][connection] [source/common/network/connection_impl.cc:456] [C0] socket event: 3
[2019-08-14 20:57:18.675][15][trace][connection] [source/common/network/connection_impl.cc:541] [C0] write ready
[2019-08-14 20:57:18.675][15][trace][connection] [source/common/network/connection_impl.cc:494] [C0] read ready
[2019-08-14 20:57:18.675][15][trace][connection] [source/common/network/raw_buffer_socket.cc:23] [C0] read returns: 0
[2019-08-14 20:57:18.675][15][debug][connection] [source/common/network/connection_impl.cc:518] [C0] remote close
[2019-08-14 20:57:18.675][15][debug][connection] [source/common/network/connection_impl.cc:188] [C0] closing socket: 0
[2019-08-14 20:57:18.675][15][debug][main] [source/server/connection_handler_impl.cc:80] [C0] adding to cleanup list
[2019-08-14 20:57:18.675][15][trace][main] [source/common/event/dispatcher_impl.cc:158] item added to deferred deletion list (size=1)
[2019-08-14 20:57:18.675][15][trace][main] [source/common/event/dispatcher_impl.cc:76] clearing deferred deletion list (size=1)
^C[2019-08-14 20:57:20.419][1][warning][main] [source/server/server.cc:468] caught SIGINT
[2019-08-14 20:57:20.419][1][info][main] [source/server/server.cc:567] shutting down server instance
[2019-08-14 20:57:20.419][1][info][main] [source/server/server.cc:521] main dispatch loop exited
[2019-08-14 20:57:20.419][11][debug][main] [source/server/worker_impl.cc:105] worker exited dispatch loop
[2019-08-14 20:57:20.419][11][debug][grpc] [source/common/grpc/google_async_client_impl.cc:33] Joining completionThread
[2019-08-14 20:57:20.419][14][debug][grpc] [source/common/grpc/google_async_client_impl.cc:66] completionThread exiting
[2019-08-14 20:57:20.419][11][debug][grpc] [source/common/grpc/google_async_client_impl.cc:35] Joined completionThread
[2019-08-14 20:57:20.419][11][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:851] shutting down thread local cluster manager
[2019-08-14 20:57:20.420][12][debug][main] [source/server/worker_impl.cc:105] worker exited dispatch loop
[2019-08-14 20:57:20.420][12][debug][grpc] [source/common/grpc/google_async_client_impl.cc:33] Joining completionThread
[2019-08-14 20:57:20.420][16][debug][grpc] [source/common/grpc/google_async_client_impl.cc:66] completionThread exiting
[2019-08-14 20:57:20.420][12][debug][grpc] [source/common/grpc/google_async_client_impl.cc:35] Joined completionThread
[2019-08-14 20:57:20.420][12][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:851] shutting down thread local cluster manager
[2019-08-14 20:57:20.420][13][debug][main] [source/server/worker_impl.cc:105] worker exited dispatch loop
[2019-08-14 20:57:20.420][13][debug][grpc] [source/common/grpc/google_async_client_impl.cc:33] Joining completionThread
[2019-08-14 20:57:20.420][18][debug][grpc] [source/common/grpc/google_async_client_impl.cc:66] completionThread exiting
[2019-08-14 20:57:20.420][13][debug][grpc] [source/common/grpc/google_async_client_impl.cc:35] Joined completionThread
[2019-08-14 20:57:20.420][13][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:851] shutting down thread local cluster manager
[2019-08-14 20:57:20.420][15][debug][main] [source/server/worker_impl.cc:105] worker exited dispatch loop
[2019-08-14 20:57:20.421][17][debug][grpc] [source/common/grpc/google_async_client_impl.cc:66] completionThread exiting
[2019-08-14 20:57:20.421][15][debug][grpc] [source/common/grpc/google_async_client_impl.cc:33] Joining completionThread
[2019-08-14 20:57:20.421][15][debug][grpc] [source/common/grpc/google_async_client_impl.cc:35] Joined completionThread
[2019-08-14 20:57:20.421][15][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:851] shutting down thread local cluster manager
[2019-08-14 20:57:20.421][1][debug][main] [source/server/server.cc:170] flushing stats
[2019-08-14 20:57:20.421][1][debug][init] [source/common/init/watcher_impl.cc:27] ClusterImplBase destroyed
[2019-08-14 20:57:20.421][1][debug][init] [source/common/init/watcher_impl.cc:27] init manager Cluster upstream destroyed
[2019-08-14 20:57:20.421][1][debug][grpc] [source/common/grpc/google_async_client_impl.cc:33] Joining completionThread
[2019-08-14 20:57:20.421][9][debug][grpc] [source/common/grpc/google_async_client_impl.cc:66] completionThread exiting
[2019-08-14 20:57:20.422][1][debug][grpc] [source/common/grpc/google_async_client_impl.cc:35] Joined completionThread
[2019-08-14 20:57:20.422][1][debug][upstream] [source/common/upstream/cluster_manager_impl.cc:851] shutting down thread local cluster manager
[2019-08-14 20:57:20.422][1][info][main] [source/server/server.cc:560] exiting
[2019-08-14 20:57:20.422][1][debug][init] [source/common/init/watcher_impl.cc:27] RunHelper destroyed
[2019-08-14 20:57:20.422][1][debug][init] [source/common/init/watcher_impl.cc:27] ListenerImpl destroyed
[2019-08-14 20:57:20.422][1][debug][init] [source/common/init/watcher_impl.cc:27] init manager Listener c17fb16f-0576-4d4c-a3b3-e159ac47a836 destroyed
[2019-08-14 20:57:20.423][1][debug][init] [source/common/init/watcher_impl.cc:27] init manager Server destroyed
```