GrpcSubscriptionImpl bug: send another request at destructor

[qiwzhang]

Title: GrpcSubscriptionImpl bug: send another request at destructor

Description:
It causes google_grpc implementation to fail at assertion; try to send data when Its completion_queue have been deleted.

When a GrpcMuxWatchImpl is deleted, it will ask GrpcMuxImpl to send a new request.
https://github.com/envoyproxy/envoy/blob/master/source/common/config/grpc_mux_impl.h#L68

GrpcMuxImpl destructor https://github.com/envoyproxy/envoy/blob/master/source/common/config/grpc_mux_impl.cc#L23
is setting inserted_ to false trying to disable this.

But it is too late, GrpcMuxWatchImpl is owned by grpc_mux_subscription_
https://github.com/envoyproxy/envoy/blob/master/source/common/config/grpc_subscription_impl.h#L39 which is deleted before grpc_mux_;

When GrpcMuxImpl destructor is called, all its watchers should have been removed.

Repro steps:
In this PR https://github.com/istio/envoy/pull/8/files, sds_dynamic_integation test is added. When try it run it 1000 times

bazel test //test/integration:sds_dynamic_integration_test --runs_per_test=1000

some of them failed with following backtrace:

Call Stack:

E0815 16:05:20.123250125 109 call.cc:1933] assertion failed: grpc_cq_begin_op(call->cq, notify_tag)
[2018-08-15 16:05:20.123][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:125] Caught Aborted, suspect faulting address 0x3e90000000f
[2018-08-15 16:05:20.124][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:94] Backtrace thr<109> obj</lib/x86_64-linux-gnu/libc.so.6> (If unsymbolized, use tools/stack_decode.py):
[2018-08-15 16:05:20.124][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<109> #0 0x7f13d2957428 (unknown)
[2018-08-15 16:05:20.124][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:117] thr<109> #1 0x7f13d2959029 (unknown)
[2018-08-15 16:05:20.124][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:104] thr<109> obj</home/qiwzhang/.cache/bazel/_bazel_qiwzhang/85114b85e3290f3d9d9a93c62b41d7d0/sandbox/8146193360513514347/execroot/envoy/bazel-out/k8-fastbuild/bin/test/integration/sds_dynamic_integration_test.runfiles/envoy/test/integration/sds_dynamic_integration_test>
[2018-08-15 16:05:20.134][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #2 0x73abfc call_start_batch()
[2018-08-15 16:05:20.143][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #3 0x73aed9 grpc_call_start_batch
[2018-08-15 16:05:20.153][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #4 0x68dd47 grpc::Channel::PerformOpsOnCall()
[2018-08-15 16:05:20.163][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #5 0x66859e grpc::internal::Call::PerformOps()
[2018-08-15 16:05:20.173][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #6 0x66c20c grpc::ClientAsyncReaderWriter<>::Write()
[2018-08-15 16:05:20.182][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #7 0x66343d Envoy::Grpc::GoogleAsyncStreamImpl::writeQueued()
[2018-08-15 16:05:20.189][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #8 0x66315e Envoy::Grpc::GoogleAsyncStreamImpl::sendMessage()
[2018-08-15 16:05:20.196][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #9 0xd3469d Envoy::Config::GrpcMuxImpl::sendDiscoveryRequest()
[2018-08-15 16:05:20.206][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #10 0xd370ff Envoy::Config::GrpcMuxImpl::GrpcMuxWatchImpl::~GrpcMuxWatchImpl()
[2018-08-15 16:05:20.215][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #11 0xd3715f Envoy::Config::GrpcMuxImpl::GrpcMuxWatchImpl::~GrpcMuxWatchImpl()
[2018-08-15 16:05:20.225][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #12 0x5ae0cb std::default_delete<>::operator()()
[2018-08-15 16:05:20.234][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #13 0x5ad0b6 std::unique_ptr<>::~unique_ptr()
[2018-08-15 16:05:20.242][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #14 0x8f69f6 Envoy::Config::GrpcMuxSubscriptionImpl<>::~GrpcMuxSubscriptionImpl()
[2018-08-15 16:05:20.250][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #15 0x8f7f97 Envoy::Config::GrpcSubscriptionImpl<>::~GrpcSubscriptionImpl()
[2018-08-15 16:05:20.260][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #16 0x8f7fe7 Envoy::Config::GrpcSubscriptionImpl<>::~GrpcSubscriptionImpl()
[2018-08-15 16:05:20.270][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #17 0x8f6195 std::default_delete<>::operator()()
[2018-08-15 16:05:20.279][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #18 0x8f52c0 std::unique_ptr<>::unique_ptr()
[2018-08-15 16:05:20.289][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #19 0x8f340c Envoy::Secret::SdsApi::SdsApi()
[2018-08-15 16:05:20.298][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #20 0x8f28fe __gnu_cxx::new_allocator<>::destroy<>()
[2018-08-15 16:05:20.308][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #21 0x8f277e std::allocator_traits<>::destroy<>()
[2018-08-15 16:05:20.316][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #22 0x8f2446 std::_Sp_counted_ptr_inplace<>::_M_dispose()
[2018-08-15 16:05:20.324][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #23 0x43b8d5 std::_Sp_counted_base<>::_M_release()
[2018-08-15 16:05:20.331][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #24 0x4364bc std::__shared_count<>::__shared_count()
[2018-08-15 16:05:20.339][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #25 0x8edad7 std::__shared_ptr<>::__shared_ptr()
[2018-08-15 16:05:20.347][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #26 0x8edb0f std::shared_ptr<>::~shared_ptr()
[2018-08-15 16:05:20.354][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #27 0xec8c60 Envoy::Ssl::ContextConfigImpl::~ContextConfigImpl()
[2018-08-15 16:05:20.362][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #28 0xeca7bb Envoy::Ssl::ClientContextConfigImpl::~ClientContextConfigImpl()
[2018-08-15 16:05:20.371][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #29 0xeca81d Envoy::Ssl::ClientContextConfigImpl::~ClientContextConfigImpl()
[2018-08-15 16:05:20.378][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #30 0x515d87 std::default_delete<>::operator()()
[2018-08-15 16:05:20.386][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #31 0x514452 std::unique_ptr<>::~unique_ptr()
[2018-08-15 16:05:20.393][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #32 0xebf944 Envoy::Ssl::ClientSslSocketFactory::~ClientSslSocketFactory()
[2018-08-15 16:05:20.401][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #33 0xebf99d Envoy::Ssl::ClientSslSocketFactory::~ClientSslSocketFactory()
[2018-08-15 16:05:20.409][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #34 0x443569 std::default_delete<>::operator()()
[2018-08-15 16:05:20.418][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #35 0x4394ae std::unique_ptr<>::~unique_ptr()
[2018-08-15 16:05:20.425][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #36 0xd17b39 Envoy::Upstream::ClusterInfoImpl::ClusterInfoImpl()
[2018-08-15 16:05:20.432][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #37 0xd17b89 Envoy::Upstream::ClusterInfoImpl::ClusterInfoImpl()
[2018-08-15 16:05:20.440][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #38 0x9ca94f std::default_delete<>::operator()()
[2018-08-15 16:05:20.449][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #39 0x9ccbc1 std::_Sp_counted_deleter<>::_M_dispose()
[2018-08-15 16:05:20.449][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #40 0x43b8d5 std::_Sp_counted_base<>::_M_release()
[2018-08-15 16:05:20.449][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #41 0x4364bc std::__shared_count<>::__shared_count()
[2018-08-15 16:05:20.458][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #42 0x48be45 std::__shared_ptr<>::__shared_ptr()
[2018-08-15 16:05:20.466][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #43 0x48be61 std::shared_ptr<>::~shared_ptr()
[2018-08-15 16:05:20.473][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #44 0x9c7640 Envoy::Upstream::HostDescriptionImpl::~HostDescriptionImpl()
[2018-08-15 16:05:20.482][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #45 0xd114a7 Envoy::Upstream::HostImpl::HostImpl()
[2018-08-15 16:05:20.490][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #46 0xd11509 Envoy::Upstream::HostImpl::HostImpl()
[2018-08-15 16:05:20.498][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #47 0x9cca73 std::_Sp_counted_ptr<>::_M_dispose()
[2018-08-15 16:05:20.498][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #48 0x43b8d5 std::_Sp_counted_base<>::_M_release()
[2018-08-15 16:05:20.498][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #49 0x4364bc std::__shared_count<>::__shared_count()
[2018-08-15 16:05:20.505][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #50 0x5edde7 std::__shared_ptr<>::__shared_ptr()
[2018-08-15 16:05:20.513][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #51 0x5ede29 std::shared_ptr<>::shared_ptr()
[2018-08-15 16:05:20.523][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #52 0x60b357 std::_Destroy<>()
[2018-08-15 16:05:20.532][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #53 0x605558 std::_Destroy_aux<>::__destroy<>()
[2018-08-15 16:05:20.542][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #54 0x5ff460 std::_Destroy<>()
[2018-08-15 16:05:20.552][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #55 0x5f8255 std::_Destroy<>()
[2018-08-15 16:05:20.561][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #56 0x5f1dee std::vector<>::vector()
[2018-08-15 16:05:20.573][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #57 0x614755 std::_Sp_counted_ptr<>::_M_dispose()
[2018-08-15 16:05:20.573][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #58 0x43b8d5 std::_Sp_counted_base<>::_M_release()
[2018-08-15 16:05:20.573][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #59 0x4364bc std::__shared_count<>::__shared_count()
[2018-08-15 16:05:20.581][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #60 0x5ee3f9 std::__shared_ptr<>::__shared_ptr()
[2018-08-15 16:05:20.591][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #61 0x5ee415 std::shared_ptr<>::~shared_ptr()
[2018-08-15 16:05:20.601][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] thr<109> #62 0x63d0e7 Envoy::Upstream::HostSetImpl::~HostSetImpl()
[2018-08-15 16:05:20.601][109][critical][backtrace] bazel-out/k8-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:121] end backtrace thread 109

[qiwzhang]

The trace log for the crash

RUN ] IpVersionsClientType/SdsDynamicDownstreamIntegrationTest.BasicSuccess/1
[2018-08-17 02:04:32.594][15][info][testing] test/integration/fake_upstream.cc:343] starting fake server on port 38219. Address version is v4
[2018-08-17 02:04:32.594][15][info][testing] test/integration/fake_upstream.cc:343] starting fake server on port 44165. Address version is v4
[2018-08-17 02:04:32.595][15][debug][misc] test/config/utility.cc:154] No capture path set for tests
[2018-08-17 02:04:32.596][15][debug][misc] test/integration/integration.cc:274] Running Envoy with configuration static_resources {
listeners {
name: "http"
address {
socket_address {
address: "127.0.0.1"
port_value: 0
}
}
filter_chains {
tls_context {
common_tls_context {
validation_context {
trusted_ca {
filename: "/home/qiwzhang/.cache/bazel/_bazel_qiwzhang/85114b85e3290f3d9d9a93c62b41d7d0/sandbox/1588660940065764561/execroot/envoy/bazel-out/k8-dbg/bin/test/integration/sds_dynamic_integration_test.runfiles/envoy/test/config/integration/certs/cacert.pem"
}
verify_certificate_hash: "E0:F3:C8:CE:5E:2E:A3:05:F0:70:1F:F5:12:E3:6E:2E:97:92:82:84:A2:28:BC:F7:73:32:D3:39:30:A1:B6:FD"
}
alpn_protocols: "http/1.1"
tls_certificate_sds_secret_configs {
name: "server_cert"
sds_config {
api_config_source {
api_type: GRPC
grpc_services {
google_grpc {
target_uri: "0.0.0.0:44165"
stat_prefix: "sds_cluster"
}
}
}
}
}
}
}
filters {
name: "envoy.http_connection_manager"
config {
fields {
key: "codec_type"
value {
string_value: "HTTP1"
}
}
fields {
key: "http_filters"
value {
list_value {
values {
struct_value {
fields {
key: "name"
value {
string_value: "envoy.router"
}
}
}
}
}
}
}
fields {
key: "route_config"
value {
struct_value {
fields {
key: "name"
value {
string_value: "route_config_0"
}
}
fields {
key: "virtual_hosts"
value {
list_value {
values {
struct_value {
fields {
key: "domains"
value {
list_value {
values {
string_value: "*"
}
}
}
}
fields {
key: "name"
value {
string_value: "integration"
}
}
fields {
key: "routes"
value {
list_value {
values {
struct_value {
fields {
key: "match"
value {
struct_value {
fields {
key: "prefix"
value {
string_value: "/"
}
}
}
}
}
fields {
key: "route"
value {
struct_value {
fields {
key: "cluster"
value {
string_value: "cluster_0"
}
}
}
}
}
}
}
}
}
}
}
}
}
}
}
}
}
}
fields {
key: "stat_prefix"
value {
string_value: "config_test"
}
}
}
}
}
}
clusters {
name: "cluster_0"
connect_timeout {
seconds: 5
}
hosts {
socket_address {
address: "127.0.0.1"
port_value: 38219
}
}
}
clusters {
name: "sds_cluster"
connect_timeout {
seconds: 5
}
hosts {
socket_address {
address: "127.0.0.1"
port_value: 44165
}
}
http2_protocol_options {
}
}
}
admin {
access_log_path: "/dev/null"
address {
socket_address {
address: "127.0.0.1"
port_value: 0
}
}
}

[2018-08-17 02:04:32.601][15][info][testing] test/integration/server.cc:36] starting integration test server
[2018-08-17 02:04:32.614][29][info][main] source/server/server.cc:190] initializing epoch 0 (hot restart version=disabled)
[2018-08-17 02:04:32.614][29][info][main] source/server/server.cc:192] statically linked extensions:
[2018-08-17 02:04:32.614][29][info][main] source/server/server.cc:194] access_loggers:
[2018-08-17 02:04:32.614][29][info][main] source/server/server.cc:197] filters.http: add-trailers-filter,envoy.router
[2018-08-17 02:04:32.614][29][info][main] source/server/server.cc:200] filters.listener: envoy.listener.tls_inspector
[2018-08-17 02:04:32.614][29][info][main] source/server/server.cc:203] filters.network: envoy.http_connection_manager
[2018-08-17 02:04:32.614][29][info][main] source/server/server.cc:205] stat_sinks:
[2018-08-17 02:04:32.615][29][info][main] source/server/server.cc:207] tracers:
[2018-08-17 02:04:32.615][29][info][main] source/server/server.cc:210] transport_sockets.downstream: envoy.transport_sockets.capture,raw_buffer,tls
[2018-08-17 02:04:32.615][29][info][main] source/server/server.cc:213] transport_sockets.upstream: envoy.transport_sockets.capture,raw_buffer,tls
[2018-08-17 02:04:32.637][29][debug][main] source/server/server.cc:241] admin address: 127.0.0.1:0
[2018-08-17 02:04:32.652][29][info][config] source/server/configuration_impl.cc:50] loading 0 static secret(s)
[2018-08-17 02:04:32.654][32][debug][grpc] source/common/grpc/google_async_client_impl.cc:41] completionThread running
[2018-08-17 02:04:32.669][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:820] adding TLS initial cluster cluster_0
[2018-08-17 02:04:32.670][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:820] adding TLS initial cluster sds_cluster
[2018-08-17 02:04:32.670][29][trace][upstream] source/common/upstream/upstream_impl.cc:770] Local locality: zone: "zone_name"

[2018-08-17 02:04:32.670][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:957] membership update for TLS cluster cluster_0
[2018-08-17 02:04:32.670][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:90] cm init: init complete: cluster=cluster_0 primary=0 secondary=0
[2018-08-17 02:04:32.670][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:62] cm init: adding: cluster=cluster_0 primary=0 secondary=0
[2018-08-17 02:04:32.670][29][trace][upstream] source/common/upstream/upstream_impl.cc:770] Local locality: zone: "zone_name"

[2018-08-17 02:04:32.670][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:957] membership update for TLS cluster sds_cluster
[2018-08-17 02:04:32.670][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:90] cm init: init complete: cluster=sds_cluster primary=0 secondary=0
[2018-08-17 02:04:32.670][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:62] cm init: adding: cluster=sds_cluster primary=0 secondary=0
[2018-08-17 02:04:32.670][29][info][upstream] source/common/upstream/cluster_manager_impl.cc:134] cm init: all clusters initialized
[2018-08-17 02:04:32.670][29][info][config] source/server/configuration_impl.cc:60] loading 1 listener(s)
[2018-08-17 02:04:32.671][29][debug][config] source/server/configuration_impl.cc:62] listener #0:
[2018-08-17 02:04:32.671][29][debug][config] source/server/listener_manager_impl.cc:639] begin add/update listener: name=http hash=16602624871135991325
[2018-08-17 02:04:32.676][29][debug][config] source/server/listener_manager_impl.cc:40] filter #0:
[2018-08-17 02:04:32.676][29][debug][config] source/server/listener_manager_impl.cc:41] name: envoy.http_connection_manager
[2018-08-17 02:04:32.677][29][debug][config] source/server/listener_manager_impl.cc:44] config: {"http_filters":[{"name":"envoy.router"}],"route_config":{"virtual_hosts":[{"name":"integration","domains":["*"],"routes":[{"match":{"prefix":"/"},"route":{"cluster":"cluster_0"}}]}],"name":"route_config_0"},"stat_prefix":"config_test","codec_type":"HTTP1"}
[2018-08-17 02:04:32.686][29][debug][config] source/extensions/filters/network/http_connection_manager/config.cc:277] http filter #0
[2018-08-17 02:04:32.686][29][debug][config] source/extensions/filters/network/http_connection_manager/config.cc:278] name: envoy.router
[2018-08-17 02:04:32.686][29][debug][config] source/extensions/filters/network/http_connection_manager/config.cc:282] config: {}
[2018-08-17 02:04:32.688][29][debug][config] source/server/listener_manager_impl.cc:525] add active listener: name=http, hash=16602624871135991325, address=127.0.0.1:0
[2018-08-17 02:04:32.688][29][info][config] source/server/configuration_impl.cc:94] loading tracing configuration
[2018-08-17 02:04:32.688][29][info][config] source/server/configuration_impl.cc:116] loading stats sink configuration
[2018-08-17 02:04:32.689][29][info][testing] test/integration/server.cc:109] waiting for 1 test server listeners
[2018-08-17 02:04:32.689][29][info][main] source/server/server.cc:401] all clusters initialized. initializing init manager
[2018-08-17 02:04:32.690][29][debug][upstream] source/common/config/grpc_mux_impl.cc:105] gRPC mux subscribe for type.googleapis.com/envoy.api.v2.auth.Secret
[2018-08-17 02:04:32.690][29][debug][upstream] source/common/config/grpc_mux_impl.cc:53] No stream available to sendDiscoveryRequest for type.googleapis.com/envoy.api.v2.auth.Secret
[2018-08-17 02:04:32.691][29][debug][upstream] source/common/config/grpc_mux_impl.cc:38] Establishing new gRPC bidi stream for rpc StreamSecrets(stream .envoy.api.v2.DiscoveryRequest) returns (stream .envoy.api.v2.DiscoveryResponse);

[2018-08-17 02:04:32.691][29][trace][upstream] source/common/config/grpc_mux_impl.cc:82] Sending DiscoveryRequest for type.googleapis.com/envoy.api.v2.auth.Secret: node {
id: "node_name"
cluster: "cluster_name"
locality {
zone: "zone_name"
}
build_version: "0/1.8.0-dev/redacted/DEBUG"
}
resource_names: "server_cert"
type_url: "type.googleapis.com/envoy.api.v2.auth.Secret"

[2018-08-17 02:04:32.691][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:192] Queued message to write (127 bytes)
[2018-08-17 02:04:32.691][29][info][main] source/server/server.cc:432] starting main dispatch loop
[2018-08-17 02:04:32.692][28][trace][connection] source/common/network/connection_impl.cc:232] [C8] readDisable: enabled=true disable=true
[2018-08-17 02:04:32.692][28][debug][testing] source/server/connection_handler_impl.cc:218] [C8] new connection
[2018-08-17 02:04:32.692][28][trace][connection] source/common/network/connection_impl.cc:389] [C8] socket event: 2
[2018-08-17 02:04:32.692][28][trace][connection] source/common/network/connection_impl.cc:457] [C8] write ready
[2018-08-17 02:04:32.692][15][debug][http2] source/common/http/http2/codec_impl.cc:621] [C8] setting stream-level initial window size to 268435456
[2018-08-17 02:04:32.692][15][debug][http2] source/common/http/http2/codec_impl.cc:643] [C8] updating connection-level initial window size to 268435456
[2018-08-17 02:04:32.693][32][trace][grpc] source/common/grpc/google_async_client_impl.cc:48] completionThread CQ event 0 true
[2018-08-17 02:04:32.693][28][trace][connection] source/common/network/connection_impl.cc:232] [C8] readDisable: enabled=false disable=false
[2018-08-17 02:04:32.693][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:241] handleOpCompletion op=0 ok=true inflight=1
[2018-08-17 02:04:32.693][28][trace][connection] source/common/network/connection_impl.cc:389] [C8] socket event: 3
[2018-08-17 02:04:32.693][28][trace][connection] source/common/network/connection_impl.cc:457] [C8] write ready
[2018-08-17 02:04:32.693][28][trace][connection] source/common/network/connection_impl.cc:427] [C8] read ready
[2018-08-17 02:04:32.693][28][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C8] read returns: 421
[2018-08-17 02:04:32.693][28][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C8] read returns: -1
[2018-08-17 02:04:32.693][28][trace][connection] source/common/network/raw_buffer_socket.cc:29] [C8] read error: 11
[2018-08-17 02:04:32.693][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:226] Write op dispatched
[2018-08-17 02:04:32.693][28][trace][http2] source/common/http/http2/codec_impl.cc:277] [C8] dispatching 421 bytes
[2018-08-17 02:04:32.693][32][trace][grpc] source/common/grpc/google_async_client_impl.cc:48] completionThread CQ event 3 true
[2018-08-17 02:04:32.693][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=4
[2018-08-17 02:04:32.693][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:241] handleOpCompletion op=3 ok=true inflight=2
[2018-08-17 02:04:32.693][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=1
[2018-08-17 02:04:32.693][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=8
[2018-08-17 02:04:32.693][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=6
[2018-08-17 02:04:32.693][28][trace][http2] source/common/http/http2/codec_impl.cc:292] [C8] dispatched 421 bytes
[2018-08-17 02:04:32.693][28][trace][http2] source/common/http/http2/codec_impl.cc:492] [C8] send data: bytes=15
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:326] [C8] writing 15 bytes, end_stream false
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:446] [C8] sent frame type=4
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:492] [C8] send data: bytes=9
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:326] [C8] writing 9 bytes, end_stream false
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:446] [C8] sent frame type=4
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:492] [C8] send data: bytes=17
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:326] [C8] writing 17 bytes, end_stream false
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:446] [C8] sent frame type=6
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:492] [C8] send data: bytes=13
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:326] [C8] writing 13 bytes, end_stream false
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:446] [C8] sent frame type=8
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:389] [C8] socket event: 2
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:457] [C8] write ready
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/raw_buffer_socket.cc:62] [C8] write returns: 54
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:389] [C8] socket event: 3
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:457] [C8] write ready
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/connection_impl.cc:427] [C8] read ready
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C8] read returns: 141
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C8] read returns: -1
[2018-08-17 02:04:32.694][28][trace][connection] source/common/network/raw_buffer_socket.cc:29] [C8] read error: 11
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:277] [C8] dispatching 141 bytes
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=0
[2018-08-17 02:04:32.694][28][trace][http2] source/common/http/http2/codec_impl.cc:292] [C8] dispatched 141 bytes
[2018-08-17 02:04:32.695][28][trace][http2] source/common/http/http2/codec_impl.cc:492] [C8] send data: bytes=10
[2018-08-17 02:04:32.695][28][trace][connection] source/common/network/connection_impl.cc:326] [C8] writing 10 bytes, end_stream false
[2018-08-17 02:04:32.695][28][trace][http2] source/common/http/http2/codec_impl.cc:446] [C8] sent frame type=1
[2018-08-17 02:04:32.695][28][trace][connection] source/common/network/connection_impl.cc:326] [C8] writing 636 bytes, end_stream false
[2018-08-17 02:04:32.695][28][trace][http2] source/common/http/http2/codec_impl.cc:446] [C8] sent frame type=0
[2018-08-17 02:04:32.695][28][trace][connection] source/common/network/connection_impl.cc:389] [C8] socket event: 2
[2018-08-17 02:04:32.695][28][trace][connection] source/common/network/connection_impl.cc:457] [C8] write ready
[2018-08-17 02:04:32.695][28][trace][connection] source/common/network/raw_buffer_socket.cc:62] [C8] write returns: 646
[2018-08-17 02:04:32.695][32][trace][grpc] source/common/grpc/google_async_client_impl.cc:48] completionThread CQ event 1 true
[2018-08-17 02:04:32.695][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:241] handleOpCompletion op=1 ok=true inflight=1
[2018-08-17 02:04:32.695][32][trace][grpc] source/common/grpc/google_async_client_impl.cc:48] completionThread CQ event 2 true
[2018-08-17 02:04:32.695][15][debug][testing] ./test/integration/fake_upstream.h:91] Sent gRPC message: version_info: "1"
resources {
[type.googleapis.com/envoy.api.v2.auth.Secret] {
name: "server_cert"
tls_certificate {
certificate_chain {
filename: "/home/qiwzhang/.cache/bazel/_bazel_qiwzhang/85114b85e3290f3d9d9a93c62b41d7d0/sandbox/1588660940065764561/execroot/envoy/bazel-out/k8-dbg/bin/test/integration/sds_dynamic_integration_test.runfiles/envoy//test/config/integration/certs/servercert.pem"
}
private_key {
filename: "/home/qiwzhang/.cache/bazel/_bazel_qiwzhang/85114b85e3290f3d9d9a93c62b41d7d0/sandbox/1588660940065764561/execroot/envoy/bazel-out/k8-dbg/bin/test/integration/sds_dynamic_integration_test.runfiles/envoy//test/config/integration/certs/serverkey.pem"
}
}
}
}
type_url: "type.googleapis.com/envoy.api.v2.auth.Secret"

[2018-08-17 02:04:32.695][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:241] handleOpCompletion op=2 ok=true inflight=1
[2018-08-17 02:04:32.695][29][debug][upstream] source/common/config/grpc_mux_impl.cc:165] Received gRPC message for type.googleapis.com/envoy.api.v2.auth.Secret at version 1
[2018-08-17 02:04:32.696][29][debug][config] source/common/ssl/ssl_socket.cc:476] Secret is updated.
[2018-08-17 02:04:32.701][29][info][config] source/server/listener_manager_impl.cc:909] all dependencies initialized. starting workers
[2018-08-17 02:04:32.702][29][debug][config] bazel-out/k8-dbg/bin/source/common/config/_virtual_includes/grpc_mux_subscription_lib/common/config/grpc_mux_subscription_impl.h:60] gRPC config for type.googleapis.com/envoy.api.v2.auth.Secret accepted with 1 resources: [name: "server_cert"
tls_certificate {
certificate_chain {
filename: "/home/qiwzhang/.cache/bazel/_bazel_qiwzhang/85114b85e3290f3d9d9a93c62b41d7d0/sandbox/1588660940065764561/execroot/envoy/bazel-out/k8-dbg/bin/test/integration/sds_dynamic_integration_test.runfiles/envoy//test/config/integration/certs/servercert.pem"
}
private_key {
filename: "/home/qiwzhang/.cache/bazel/_bazel_qiwzhang/85114b85e3290f3d9d9a93c62b41d7d0/sandbox/1588660940065764561/execroot/envoy/bazel-out/k8-dbg/bin/test/integration/sds_dynamic_integration_test.runfiles/envoy//test/config/integration/certs/serverkey.pem"
}
}
]
[2018-08-17 02:04:32.702][29][trace][upstream] source/common/config/grpc_mux_impl.cc:82] Sending DiscoveryRequest for type.googleapis.com/envoy.api.v2.auth.Secret: version_info: "1"
node {
id: "node_name"
cluster: "cluster_name"
locality {
zone: "zone_name"
}
build_version: "0/1.8.0-dev/redacted/DEBUG"
}
resource_names: "server_cert"
type_url: "type.googleapis.com/envoy.api.v2.auth.Secret"

[2018-08-17 02:04:32.702][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:192] Queued message to write (130 bytes)
[2018-08-17 02:04:32.702][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:226] Write op dispatched
[2018-08-17 02:04:32.702][28][trace][connection] source/common/network/connection_impl.cc:389] [C8] socket event: 3
[2018-08-17 02:04:32.702][28][trace][connection] source/common/network/connection_impl.cc:457] [C8] write ready
[2018-08-17 02:04:32.702][28][trace][connection] source/common/network/connection_impl.cc:427] [C8] read ready
[2018-08-17 02:04:32.703][28][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C8] read returns: 179
[2018-08-17 02:04:32.703][28][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C8] read returns: -1
[2018-08-17 02:04:32.703][28][trace][connection] source/common/network/raw_buffer_socket.cc:29] [C8] read error: 11
[2018-08-17 02:04:32.703][28][trace][http2] source/common/http/http2/codec_impl.cc:277] [C8] dispatching 179 bytes
[2018-08-17 02:04:32.703][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=4
[2018-08-17 02:04:32.703][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=8
[2018-08-17 02:04:32.703][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=0
[2018-08-17 02:04:32.703][28][trace][http2] source/common/http/http2/codec_impl.cc:335] [C8] recv frame type=8
[2018-08-17 02:04:32.703][28][trace][http2] source/common/http/http2/codec_impl.cc:292] [C8] dispatched 179 bytes
[2018-08-17 02:04:32.703][32][trace][grpc] source/common/grpc/google_async_client_impl.cc:48] completionThread CQ event 3 true
[2018-08-17 02:04:32.703][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:241] handleOpCompletion op=3 ok=true inflight=2
[2018-08-17 02:04:32.709][34][debug][main] source/server/worker_impl.cc:91] worker entering dispatch loop
[2018-08-17 02:04:32.710][34][debug][upstream] source/common/upstream/cluster_manager_impl.cc:820] adding TLS initial cluster cluster_0
[2018-08-17 02:04:32.710][35][debug][grpc] source/common/grpc/google_async_client_impl.cc:41] completionThread running
[2018-08-17 02:04:32.710][34][debug][upstream] source/common/upstream/cluster_manager_impl.cc:820] adding TLS initial cluster sds_cluster
[2018-08-17 02:04:32.711][34][debug][upstream] source/common/upstream/cluster_manager_impl.cc:957] membership update for TLS cluster cluster_0
[2018-08-17 02:04:32.711][34][debug][upstream] source/common/upstream/cluster_manager_impl.cc:957] membership update for TLS cluster sds_cluster
[2018-08-17 02:04:32.712][15][info][testing] test/integration/server.cc:55] listener wait complete
[2018-08-17 02:04:32.735][15][debug][client] source/common/http/codec_client.cc:25] [C9] connecting
[2018-08-17 02:04:32.735][15][debug][connection] source/common/network/connection_impl.cc:572] [C9] connecting to 127.0.0.1:41321
[2018-08-17 02:04:32.736][15][debug][connection] source/common/network/connection_impl.cc:581] [C9] connection in progress
[2018-08-17 02:04:32.736][15][trace][connection] source/common/network/connection_impl.cc:389] [C9] socket event: 2
[2018-08-17 02:04:32.736][15][trace][connection] source/common/network/connection_impl.cc:457] [C9] write ready
[2018-08-17 02:04:32.736][15][debug][connection] source/common/network/connection_impl.cc:466] [C9] connected
[2018-08-17 02:04:32.736][34][debug][main] source/server/connection_handler_impl.cc:218] [C10] new connection
[2018-08-17 02:04:32.736][15][debug][connection] source/common/ssl/ssl_socket.cc:145] [C9] handshake error: 2
[2018-08-17 02:04:32.736][34][trace][connection] source/common/network/connection_impl.cc:389] [C10] socket event: 3
[2018-08-17 02:04:32.736][34][trace][connection] source/common/network/connection_impl.cc:457] [C10] write ready
[2018-08-17 02:04:32.739][34][debug][connection] source/common/ssl/ssl_socket.cc:145] [C10] handshake error: 2
[2018-08-17 02:04:32.739][15][trace][connection] source/common/network/connection_impl.cc:389] [C9] socket event: 3
[2018-08-17 02:04:32.739][34][trace][connection] source/common/network/connection_impl.cc:427] [C10] read ready
[2018-08-17 02:04:32.739][15][trace][connection] source/common/network/connection_impl.cc:457] [C9] write ready
[2018-08-17 02:04:32.739][34][debug][connection] source/common/ssl/ssl_socket.cc:145] [C10] handshake error: 2
[2018-08-17 02:04:32.747][15][debug][connection] source/common/ssl/ssl_socket.cc:145] [C9] handshake error: 2
[2018-08-17 02:04:32.747][15][trace][connection] source/common/network/connection_impl.cc:427] [C9] read ready
[2018-08-17 02:04:32.747][15][debug][connection] source/common/ssl/ssl_socket.cc:145] [C9] handshake error: 2
[2018-08-17 02:04:32.747][34][trace][connection] source/common/network/connection_impl.cc:389] [C10] socket event: 3
[2018-08-17 02:04:32.748][34][trace][connection] source/common/network/connection_impl.cc:457] [C10] write ready
[2018-08-17 02:04:32.751][34][debug][connection] source/common/ssl/ssl_socket.cc:134] [C10] handshake complete
[2018-08-17 02:04:32.751][15][trace][connection] source/common/network/connection_impl.cc:389] [C9] socket event: 3
[2018-08-17 02:04:32.751][15][trace][connection] source/common/network/connection_impl.cc:457] [C9] write ready
[2018-08-17 02:04:32.751][15][debug][connection] source/common/ssl/ssl_socket.cc:134] [C9] handshake complete
[2018-08-17 02:04:32.752][15][debug][client] source/common/http/codec_client.cc:63] [C9] connected
[2018-08-17 02:04:32.752][15][trace][connection] source/common/network/connection_impl.cc:427] [C9] read ready
[2018-08-17 02:04:32.752][15][trace][connection] source/common/ssl/ssl_socket.cc:92] [C9] ssl read returns: -1
[2018-08-17 02:04:32.752][34][trace][connection] source/common/network/connection_impl.cc:427] [C10] read ready
[2018-08-17 02:04:32.752][34][trace][connection] source/common/ssl/ssl_socket.cc:92] [C10] ssl read returns: -1
[2018-08-17 02:04:32.752][15][trace][connection] source/common/network/connection_impl.cc:326] [C9] writing 83 bytes, end_stream false
[2018-08-17 02:04:32.752][15][trace][connection] source/common/network/connection_impl.cc:389] [C9] socket event: 2
[2018-08-17 02:04:32.752][15][trace][connection] source/common/network/connection_impl.cc:457] [C9] write ready
[2018-08-17 02:04:32.752][15][trace][connection] source/common/ssl/ssl_socket.cc:207] [C9] ssl write returns: 83
[2018-08-17 02:04:32.752][34][trace][connection] source/common/network/connection_impl.cc:389] [C10] socket event: 3
[2018-08-17 02:04:32.752][34][trace][connection] source/common/network/connection_impl.cc:457] [C10] write ready
[2018-08-17 02:04:32.752][34][trace][connection] source/common/network/connection_impl.cc:427] [C10] read ready
[2018-08-17 02:04:32.752][34][trace][connection] source/common/ssl/ssl_socket.cc:92] [C10] ssl read returns: 83
[2018-08-17 02:04:32.752][34][trace][connection] source/common/ssl/ssl_socket.cc:92] [C10] ssl read returns: -1
[2018-08-17 02:04:32.752][34][trace][http] source/common/http/http1/codec_impl.cc:341] [C10] parsing 83 bytes
[2018-08-17 02:04:32.752][34][trace][http] source/common/http/http1/codec_impl.cc:439] [C10] message begin
[2018-08-17 02:04:32.752][34][debug][http] source/common/http/conn_manager_impl.cc:190] [C10] new stream
[2018-08-17 02:04:32.753][34][trace][http] source/common/http/http1/codec_impl.cc:309] [C10] completed header: key=host value=host
[2018-08-17 02:04:32.753][34][trace][http] source/common/http/http1/codec_impl.cc:309] [C10] completed header: key=x-lyft-user-id value=123
[2018-08-17 02:04:32.753][34][trace][http] source/common/http/http1/codec_impl.cc:405] [C10] headers complete
[2018-08-17 02:04:32.753][34][trace][http] source/common/http/http1/codec_impl.cc:309] [C10] completed header: key=content-length value=0
[2018-08-17 02:04:32.753][34][trace][http] source/common/http/http1/codec_impl.cc:426] [C10] message complete
[2018-08-17 02:04:32.753][34][debug][http] source/common/http/conn_manager_impl.cc:889] [C10][S17963119814636879959] request end stream
[2018-08-17 02:04:32.753][34][debug][http] source/common/http/conn_manager_impl.cc:490] [C10][S17963119814636879959] request headers complete (end_stream=true):
':authority', 'host'
':path', '/test/long/url'
':method', 'GET'
'x-lyft-user-id', '123'
'content-length', '0'

[2018-08-17 02:04:32.753][34][debug][router] source/common/router/router.cc:252] [C10][S17963119814636879959] cluster 'cluster_0' match for URL '/test/long/url'
[2018-08-17 02:04:32.753][34][debug][router] source/common/router/router.cc:303] [C10][S17963119814636879959] router decoding headers:
':authority', 'host'
':path', '/test/long/url'
':method', 'GET'
':scheme', 'http'
'x-lyft-user-id', '123'
'content-length', '0'
'x-forwarded-proto', 'https'
'x-request-id', 'c2193114-a198-4adb-9499-8cdc5efb2245'
'x-envoy-expected-rq-timeout-ms', '15000'

[2018-08-17 02:04:32.754][34][debug][pool] source/common/http/http1/conn_pool.cc:78] creating a new connection
[2018-08-17 02:04:32.754][34][debug][client] source/common/http/codec_client.cc:25] [C11] connecting
[2018-08-17 02:04:32.754][34][debug][connection] source/common/network/connection_impl.cc:572] [C11] connecting to 127.0.0.1:38219
[2018-08-17 02:04:32.754][34][debug][connection] source/common/network/connection_impl.cc:581] [C11] connection in progress
[2018-08-17 02:04:32.754][34][debug][pool] source/common/http/http1/conn_pool.cc:106] queueing request due to no available connections
[2018-08-17 02:04:32.754][34][trace][http] source/common/http/conn_manager_impl.cc:719] [C10][S17963119814636879959] decode headers called: filter=0x607000060810 status=1
[2018-08-17 02:04:32.754][34][trace][http] source/common/http/http1/codec_impl.cc:362] [C10] parsed 83 bytes
[2018-08-17 02:04:32.754][34][trace][connection] source/common/network/connection_impl.cc:232] [C10] readDisable: enabled=true disable=true
[2018-08-17 02:04:32.754][34][trace][connection] source/common/network/connection_impl.cc:389] [C11] socket event: 2
[2018-08-17 02:04:32.754][34][trace][connection] source/common/network/connection_impl.cc:457] [C11] write ready
[2018-08-17 02:04:32.754][34][debug][connection] source/common/network/connection_impl.cc:466] [C11] connected
[2018-08-17 02:04:32.754][34][debug][client] source/common/http/codec_client.cc:63] [C11] connected
[2018-08-17 02:04:32.755][34][debug][pool] source/common/http/http1/conn_pool.cc:251] [C11] attaching to next request
[2018-08-17 02:04:32.755][34][debug][router] source/common/router/router.cc:971] [C10][S17963119814636879959] pool ready
[2018-08-17 02:04:32.755][34][trace][connection] source/common/network/connection_impl.cc:326] [C11] writing 200 bytes, end_stream false
[2018-08-17 02:04:32.755][27][trace][connection] source/common/network/connection_impl.cc:232] [C12] readDisable: enabled=true disable=true
[2018-08-17 02:04:32.755][27][debug][testing] source/server/connection_handler_impl.cc:218] [C12] new connection
[2018-08-17 02:04:32.755][27][trace][connection] source/common/network/connection_impl.cc:389] [C12] socket event: 2
[2018-08-17 02:04:32.755][27][trace][connection] source/common/network/connection_impl.cc:457] [C12] write ready
[2018-08-17 02:04:32.755][27][trace][connection] source/common/network/connection_impl.cc:232] [C12] readDisable: enabled=false disable=false
[2018-08-17 02:04:32.755][27][trace][connection] source/common/network/connection_impl.cc:389] [C12] socket event: 2
[2018-08-17 02:04:32.755][27][trace][connection] source/common/network/connection_impl.cc:457] [C12] write ready
[2018-08-17 02:04:32.755][34][trace][connection] source/common/network/connection_impl.cc:457] [C11] write ready
[2018-08-17 02:04:32.757][34][trace][connection] source/common/network/raw_buffer_socket.cc:62] [C11] write returns: 200
[2018-08-17 02:04:32.757][34][trace][connection] source/common/network/connection_impl.cc:389] [C10] socket event: 2
[2018-08-17 02:04:32.757][34][trace][connection] source/common/network/connection_impl.cc:457] [C10] write ready
[2018-08-17 02:04:32.757][34][trace][connection] source/common/network/connection_impl.cc:389] [C11] socket event: 2
[2018-08-17 02:04:32.757][34][trace][connection] source/common/network/connection_impl.cc:457] [C11] write ready
[2018-08-17 02:04:32.757][27][trace][connection] source/common/network/connection_impl.cc:389] [C12] socket event: 3
[2018-08-17 02:04:32.757][27][trace][connection] source/common/network/connection_impl.cc:457] [C12] write ready
[2018-08-17 02:04:32.757][27][trace][connection] source/common/network/connection_impl.cc:427] [C12] read ready
[2018-08-17 02:04:32.757][27][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C12] read returns: 200
[2018-08-17 02:04:32.757][27][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C12] read returns: -1
[2018-08-17 02:04:32.757][27][trace][connection] source/common/network/raw_buffer_socket.cc:29] [C12] read error: 11
[2018-08-17 02:04:32.757][27][trace][http] source/common/http/http1/codec_impl.cc:341] [C12] parsing 200 bytes
[2018-08-17 02:04:32.757][27][trace][http] source/common/http/http1/codec_impl.cc:439] [C12] message begin
[2018-08-17 02:04:32.757][27][trace][http] source/common/http/http1/codec_impl.cc:309] [C12] completed header: key=host value=host
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:309] [C12] completed header: key=x-lyft-user-id value=123
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:309] [C12] completed header: key=content-length value=0
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:309] [C12] completed header: key=x-forwarded-proto value=https
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:309] [C12] completed header: key=x-request-id value=c2193114-a198-4adb-9499-8cdc5efb2245
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:405] [C12] headers complete
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:309] [C12] completed header: key=x-envoy-expected-rq-timeout-ms value=15000
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:426] [C12] message complete
[2018-08-17 02:04:32.758][27][trace][http] source/common/http/http1/codec_impl.cc:362] [C12] parsed 200 bytes
[2018-08-17 02:04:32.758][27][trace][connection] source/common/network/connection_impl.cc:326] [C12] writing 38 bytes, end_stream false
[2018-08-17 02:04:32.758][27][trace][connection] source/common/network/connection_impl.cc:389] [C12] socket event: 2
[2018-08-17 02:04:32.758][27][trace][connection] source/common/network/connection_impl.cc:457] [C12] write ready
[2018-08-17 02:04:32.759][27][trace][connection] source/common/network/raw_buffer_socket.cc:62] [C12] write returns: 38
[2018-08-17 02:04:32.759][34][trace][connection] source/common/network/connection_impl.cc:389] [C11] socket event: 3
[2018-08-17 02:04:32.759][34][trace][connection] source/common/network/connection_impl.cc:457] [C11] write ready
[2018-08-17 02:04:32.759][34][trace][connection] source/common/network/connection_impl.cc:427] [C11] read ready
[2018-08-17 02:04:32.759][34][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C11] read returns: 38
[2018-08-17 02:04:32.759][34][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C11] read returns: -1
[2018-08-17 02:04:32.759][34][trace][connection] source/common/network/raw_buffer_socket.cc:29] [C11] read error: 11
[2018-08-17 02:04:32.759][34][trace][http] source/common/http/http1/codec_impl.cc:341] [C11] parsing 38 bytes
[2018-08-17 02:04:32.759][34][trace][http] source/common/http/http1/codec_impl.cc:439] [C11] message begin
[2018-08-17 02:04:32.759][34][trace][http] source/common/http/http1/codec_impl.cc:405] [C11] headers complete
[2018-08-17 02:04:32.759][34][trace][http] source/common/http/http1/codec_impl.cc:309] [C11] completed header: key=content-length value=0
[2018-08-17 02:04:32.759][34][debug][router] source/common/router/router.cc:583] [C10][S17963119814636879959] upstream headers complete: end_stream=false
[2018-08-17 02:04:32.761][34][debug][http] source/common/http/conn_manager_impl.cc:1083] [C10][S17963119814636879959] encoding headers via codec (end_stream=false):
':status', '200'
'content-length', '0'
'x-envoy-upstream-service-time', '5'
'date', 'Fri, 17 Aug 2018 02:04:32 GMT'
'server', 'envoy'

[2018-08-17 02:04:32.761][34][trace][connection] source/common/network/connection_impl.cc:326] [C10] writing 124 bytes, end_stream false
[2018-08-17 02:04:32.761][34][trace][http] source/common/http/http1/codec_impl.cc:426] [C11] message complete
[2018-08-17 02:04:32.761][34][trace][http] source/common/http/http1/codec_impl.cc:729] [C11] message complete
[2018-08-17 02:04:32.761][34][debug][client] source/common/http/codec_client.cc:94] [C11] response complete
[2018-08-17 02:04:32.761][34][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.762][34][trace][http] source/common/http/conn_manager_impl.cc:1170] [C10][S17963119814636879959] encoding data via codec (size=0 end_stream=true)
[2018-08-17 02:04:32.763][34][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=2)
[2018-08-17 02:04:32.763][34][trace][connection] source/common/network/connection_impl.cc:232] [C10] readDisable: enabled=false disable=false
[2018-08-17 02:04:32.763][34][debug][pool] source/common/http/http1/conn_pool.cc:208] [C11] response complete
[2018-08-17 02:04:32.763][34][debug][pool] source/common/http/http1/conn_pool.cc:246] [C11] moving to ready
[2018-08-17 02:04:32.763][34][trace][http] source/common/http/http1/codec_impl.cc:362] [C11] parsed 38 bytes
[2018-08-17 02:04:32.763][34][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=2)
[2018-08-17 02:04:32.763][34][trace][connection] source/common/network/connection_impl.cc:389] [C10] socket event: 2
[2018-08-17 02:04:32.763][34][trace][connection] source/common/network/connection_impl.cc:457] [C10] write ready
[2018-08-17 02:04:32.763][34][trace][connection] source/common/ssl/ssl_socket.cc:207] [C10] ssl write returns: 124
[2018-08-17 02:04:32.763][15][trace][connection] source/common/network/connection_impl.cc:389] [C9] socket event: 3
[2018-08-17 02:04:32.763][15][trace][connection] source/common/network/connection_impl.cc:457] [C9] write ready
[2018-08-17 02:04:32.764][15][trace][connection] source/common/network/connection_impl.cc:427] [C9] read ready
[2018-08-17 02:04:32.764][15][trace][connection] source/common/ssl/ssl_socket.cc:92] [C9] ssl read returns: 124
[2018-08-17 02:04:32.764][15][trace][connection] source/common/ssl/ssl_socket.cc:92] [C9] ssl read returns: -1
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:341] [C9] parsing 124 bytes
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:439] [C9] message begin
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C9] completed header: key=content-length value=0
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C9] completed header: key=x-envoy-upstream-service-time value=5
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C9] completed header: key=date value=Fri, 17 Aug 2018 02:04:32 GMT
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:405] [C9] headers complete
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C9] completed header: key=server value=envoy
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:426] [C9] message complete
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:729] [C9] message complete
[2018-08-17 02:04:32.764][15][debug][client] source/common/http/codec_client.cc:94] [C9] response complete
[2018-08-17 02:04:32.764][15][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.764][15][trace][http] source/common/http/http1/codec_impl.cc:362] [C9] parsed 124 bytes
[2018-08-17 02:04:32.764][15][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.765][28][debug][connection] source/common/network/connection_impl.cc:98] [C8] closing data_to_write=0 type=0
[2018-08-17 02:04:32.765][28][debug][connection] source/common/network/connection_impl.cc:133] [C8] closing socket: 1
[2018-08-17 02:04:32.765][28][debug][testing] source/server/connection_handler_impl.cc:51] [C8] adding to cleanup list
[2018-08-17 02:04:32.765][28][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.765][28][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.765][15][trace][testing] test/integration/fake_upstream.cc:243] FakeConnectionBase waiting for disconnect
[2018-08-17 02:04:32.766][15][trace][testing] test/integration/fake_upstream.cc:264] FakeConnectionBase done waiting for disconnect
[2018-08-17 02:04:32.766][27][debug][connection] source/common/network/connection_impl.cc:98] [C12] closing data_to_write=0 type=0
[2018-08-17 02:04:32.766][27][debug][connection] source/common/network/connection_impl.cc:133] [C12] closing socket: 1
[2018-08-17 02:04:32.766][27][debug][testing] source/server/connection_handler_impl.cc:51] [C12] adding to cleanup list
[2018-08-17 02:04:32.766][34][trace][connection] source/common/network/connection_impl.cc:389] [C11] socket event: 3
[2018-08-17 02:04:32.766][27][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.766][34][trace][connection] source/common/network/connection_impl.cc:457] [C11] write ready
[2018-08-17 02:04:32.766][27][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.766][15][trace][testing] test/integration/fake_upstream.cc:243] FakeConnectionBase waiting for disconnect
[2018-08-17 02:04:32.766][34][trace][connection] source/common/network/connection_impl.cc:427] [C11] read ready
[2018-08-17 02:04:32.766][15][trace][testing] test/integration/fake_upstream.cc:264] FakeConnectionBase done waiting for disconnect
[2018-08-17 02:04:32.766][15][debug][connection] source/common/network/connection_impl.cc:98] [C9] closing data_to_write=0 type=1
[2018-08-17 02:04:32.766][15][debug][connection] source/common/network/connection_impl.cc:133] [C9] closing socket: 1
[2018-08-17 02:04:32.766][34][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C11] read returns: 0
[2018-08-17 02:04:32.766][15][debug][connection] source/common/ssl/ssl_socket.cc:243] [C9] SSL shutdown: rc=0
[2018-08-17 02:04:32.766][34][debug][connection] source/common/network/connection_impl.cc:451] [C11] remote close
[2018-08-17 02:04:32.766][15][debug][client] source/common/http/codec_client.cc:81] [C9] disconnect. resetting 0 pending requests
[2018-08-17 02:04:32.766][34][debug][connection] source/common/network/connection_impl.cc:133] [C11] closing socket: 0
[2018-08-17 02:04:32.766][34][debug][client] source/common/http/codec_client.cc:81] [C11] disconnect. resetting 0 pending requests
[2018-08-17 02:04:32.766][34][debug][pool] source/common/http/http1/conn_pool.cc:122] [C11] client disconnected
[2018-08-17 02:04:32.767][34][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.767][34][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.767][34][trace][connection] source/common/network/connection_impl.cc:389] [C10] socket event: 3
[2018-08-17 02:04:32.767][34][trace][connection] source/common/network/connection_impl.cc:457] [C10] write ready
[2018-08-17 02:04:32.767][34][trace][connection] source/common/network/connection_impl.cc:427] [C10] read ready
[2018-08-17 02:04:32.767][34][trace][connection] source/common/ssl/ssl_socket.cc:92] [C10] ssl read returns: 0
[2018-08-17 02:04:32.767][34][debug][connection] source/common/network/connection_impl.cc:451] [C10] remote close
[2018-08-17 02:04:32.767][34][debug][connection] source/common/network/connection_impl.cc:133] [C10] closing socket: 0
[2018-08-17 02:04:32.767][34][debug][connection] source/common/ssl/ssl_socket.cc:243] [C10] SSL shutdown: rc=1
[2018-08-17 02:04:32.767][34][debug][main] source/server/connection_handler_impl.cc:51] [C10] adding to cleanup list
[2018-08-17 02:04:32.767][34][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.768][34][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.768][15][info][testing] test/integration/server.cc:59] stopping integration test server
[2018-08-17 02:04:32.770][15][debug][client] source/common/http/codec_client.cc:25] [C13] connecting
[2018-08-17 02:04:32.770][15][debug][connection] source/common/network/connection_impl.cc:572] [C13] connecting to 127.0.0.1:41753
[2018-08-17 02:04:32.770][15][debug][connection] source/common/network/connection_impl.cc:581] [C13] connection in progress
[2018-08-17 02:04:32.771][29][debug][main] source/server/connection_handler_impl.cc:218] [C14] new connection
[2018-08-17 02:04:32.771][15][trace][connection] source/common/network/connection_impl.cc:326] [C13] writing 62 bytes, end_stream false
[2018-08-17 02:04:32.771][15][trace][connection] source/common/network/connection_impl.cc:389] [C13] socket event: 2
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/connection_impl.cc:389] [C14] socket event: 2
[2018-08-17 02:04:32.771][15][trace][connection] source/common/network/connection_impl.cc:457] [C13] write ready
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/connection_impl.cc:457] [C14] write ready
[2018-08-17 02:04:32.771][15][debug][connection] source/common/network/connection_impl.cc:466] [C13] connected
[2018-08-17 02:04:32.771][15][debug][client] source/common/http/codec_client.cc:63] [C13] connected
[2018-08-17 02:04:32.771][15][trace][connection] source/common/network/connection_impl.cc:457] [C13] write ready
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/connection_impl.cc:389] [C14] socket event: 3
[2018-08-17 02:04:32.771][15][trace][connection] source/common/network/raw_buffer_socket.cc:62] [C13] write returns: 62
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/connection_impl.cc:457] [C14] write ready
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/connection_impl.cc:427] [C14] read ready
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C14] read returns: 62
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C14] read returns: -1
[2018-08-17 02:04:32.771][29][trace][connection] source/common/network/raw_buffer_socket.cc:29] [C14] read error: 11
[2018-08-17 02:04:32.771][29][trace][http] source/common/http/http1/codec_impl.cc:341] [C14] parsing 62 bytes
[2018-08-17 02:04:32.771][29][trace][http] source/common/http/http1/codec_impl.cc:439] [C14] message begin
[2018-08-17 02:04:32.771][29][debug][http] source/common/http/conn_manager_impl.cc:190] [C14] new stream
[2018-08-17 02:04:32.771][29][trace][http] source/common/http/http1/codec_impl.cc:309] [C14] completed header: key=host value=host
[2018-08-17 02:04:32.771][29][trace][http] source/common/http/http1/codec_impl.cc:405] [C14] headers complete
[2018-08-17 02:04:32.771][29][trace][http] source/common/http/http1/codec_impl.cc:309] [C14] completed header: key=content-length value=0
[2018-08-17 02:04:32.771][29][trace][http] source/common/http/http1/codec_impl.cc:426] [C14] message complete
[2018-08-17 02:04:32.771][29][debug][http] source/common/http/conn_manager_impl.cc:889] [C14][S1847132448462207422] request end stream
[2018-08-17 02:04:32.771][29][debug][http] source/common/http/conn_manager_impl.cc:490] [C14][S1847132448462207422] request headers complete (end_stream=true):
':authority', 'host'
':path', '/quitquitquit'
':method', 'POST'
'content-length', '0'

[2018-08-17 02:04:32.772][29][debug][admin] source/server/http/admin.cc:843] [C14][S1847132448462207422] request complete: path: /quitquitquit
[2018-08-17 02:04:32.772][29][debug][http] source/common/http/conn_manager_impl.cc:1083] [C14][S1847132448462207422] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'text/plain; charset=UTF-8'
'cache-control', 'no-cache, max-age=0'
'x-content-type-options', 'nosniff'
'date', 'Fri, 17 Aug 2018 02:04:32 GMT'
'server', 'envoy'

[2018-08-17 02:04:32.772][29][trace][connection] source/common/network/connection_impl.cc:326] [C14] writing 209 bytes, end_stream false
[2018-08-17 02:04:32.772][29][trace][http] source/common/http/conn_manager_impl.cc:1170] [C14][S1847132448462207422] encoding data via codec (size=3 end_stream=true)
[2018-08-17 02:04:32.772][29][trace][connection] source/common/network/connection_impl.cc:326] [C14] writing 13 bytes, end_stream false
[2018-08-17 02:04:32.772][29][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.772][29][trace][http] source/common/http/conn_manager_impl.cc:719] [C14][S1847132448462207422] decode headers called: filter=0x60700006a520 status=1
[2018-08-17 02:04:32.772][29][trace][http] source/common/http/http1/codec_impl.cc:362] [C14] parsed 62 bytes
[2018-08-17 02:04:32.772][29][trace][connection] source/common/network/connection_impl.cc:389] [C14] socket event: 2
[2018-08-17 02:04:32.772][29][trace][connection] source/common/network/connection_impl.cc:457] [C14] write ready
[2018-08-17 02:04:32.772][15][trace][connection] source/common/network/connection_impl.cc:389] [C13] socket event: 3
[2018-08-17 02:04:32.772][15][trace][connection] source/common/network/connection_impl.cc:457] [C13] write ready
[2018-08-17 02:04:32.772][29][trace][connection] source/common/network/raw_buffer_socket.cc:62] [C14] write returns: 222
[2018-08-17 02:04:32.772][15][trace][connection] source/common/network/connection_impl.cc:427] [C13] read ready
[2018-08-17 02:04:32.772][29][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.772][15][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C13] read returns: 222
[2018-08-17 02:04:32.772][15][trace][connection] source/common/network/raw_buffer_socket.cc:21] [C13] read returns: -1
[2018-08-17 02:04:32.772][15][trace][connection] source/common/network/raw_buffer_socket.cc:29] [C13] read error: 11
[2018-08-17 02:04:32.772][15][trace][http] source/common/http/http1/codec_impl.cc:341] [C13] parsing 222 bytes
[2018-08-17 02:04:32.772][15][trace][http] source/common/http/http1/codec_impl.cc:439] [C13] message begin
[2018-08-17 02:04:32.772][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C13] completed header: key=content-type value=text/plain; charset=UTF-8
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C13] completed header: key=cache-control value=no-cache, max-age=0
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C13] completed header: key=x-content-type-options value=nosniff
[2018-08-17 02:04:32.773][29][info][main] source/server/server.cc:436] main dispatch loop exited
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C13] completed header: key=date value=Fri, 17 Aug 2018 02:04:32 GMT
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C13] completed header: key=server value=envoy
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:405] [C13] headers complete
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:309] [C13] completed header: key=transfer-encoding value=chunked
[2018-08-17 02:04:32.773][34][debug][main] source/server/worker_impl.cc:95] worker exited dispatch loop
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:426] [C13] message complete
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:729] [C13] message complete
[2018-08-17 02:04:32.773][15][debug][client] source/common/http/codec_client.cc:94] [C13] response complete
[2018-08-17 02:04:32.773][15][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.773][15][debug][connection] source/common/network/connection_impl.cc:98] [C13] closing data_to_write=0 type=1
[2018-08-17 02:04:32.773][34][debug][grpc] source/common/grpc/google_async_client_impl.cc:31] Joining completionThread
[2018-08-17 02:04:32.773][35][debug][grpc] source/common/grpc/google_async_client_impl.cc:64] completionThread exiting
[2018-08-17 02:04:32.773][15][debug][connection] source/common/network/connection_impl.cc:133] [C13] closing socket: 1
[2018-08-17 02:04:32.773][15][debug][client] source/common/http/codec_client.cc:81] [C13] disconnect. resetting 0 pending requests
[2018-08-17 02:04:32.773][15][trace][http] source/common/http/http1/codec_impl.cc:362] [C13] parsed 222 bytes
[2018-08-17 02:04:32.773][15][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.774][32][trace][grpc] source/common/grpc/google_async_client_impl.cc:48] completionThread CQ event 2 false
[2018-08-17 02:04:32.774][34][debug][grpc] source/common/grpc/google_async_client_impl.cc:33] Joined completionThread
[2018-08-17 02:04:32.774][34][debug][upstream] source/common/upstream/cluster_manager_impl.cc:834] shutting down thread local cluster manager
[2018-08-17 02:04:32.774][29][debug][main] source/server/server.cc:126] flushing stats
[2018-08-17 02:04:32.775][29][debug][connection] source/common/network/connection_impl.cc:98] [C14] closing data_to_write=0 type=1
[2018-08-17 02:04:32.775][29][debug][connection] source/common/network/connection_impl.cc:133] [C14] closing socket: 1
[2018-08-17 02:04:32.775][29][debug][main] source/server/connection_handler_impl.cc:51] [C14] adding to cleanup list
[2018-08-17 02:04:32.775][29][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.775][29][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-08-17 02:04:32.775][29][debug][grpc] source/common/grpc/google_async_client_impl.cc:203] resetStream
[2018-08-17 02:04:32.775][29][debug][grpc] source/common/grpc/google_async_client_impl.cc:364] Stream cleanup with 1 in-flight tags
[2018-08-17 02:04:32.776][29][debug][grpc] source/common/grpc/google_async_client_impl.cc:31] Joining completionThread
[2018-08-17 02:04:32.776][32][debug][grpc] source/common/grpc/google_async_client_impl.cc:64] completionThread exiting
[2018-08-17 02:04:32.776][29][debug][grpc] source/common/grpc/google_async_client_impl.cc:33] Joined completionThread
[2018-08-17 02:04:32.776][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:241] handleOpCompletion op=2 ok=false inflight=1
[2018-08-17 02:04:32.776][29][debug][grpc] source/common/grpc/google_async_client_impl.cc:353] Deferred delete
[2018-08-17 02:04:32.776][29][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-08-17 02:04:32.776][29][debug][upstream] source/common/upstream/cluster_manager_impl.cc:834] shutting down thread local cluster manager
[2018-08-17 02:04:32.778][29][info][main] source/server/server.cc:472] exiting
[2018-08-17 02:04:32.779][29][debug][secret] source/common/secret/secret_manager_impl.cc:42] Unregister secret provider. hash key: 17318959245829543372server_cert
[2018-08-17 02:04:32.780][29][trace][upstream] source/common/config/grpc_mux_impl.cc:82] Sending DiscoveryRequest for type.googleapis.com/envoy.api.v2.auth.Secret: version_info: "1"
node {
id: "node_name"
cluster: "cluster_name"
locality {
zone: "zone_name"
}
build_version: "0/1.8.0-dev/redacted/DEBUG"
}
type_url: "type.googleapis.com/envoy.api.v2.auth.Secret"

[2018-08-17 02:04:32.780][29][trace][grpc] source/common/grpc/google_async_client_impl.cc:192] Queued message to write (117 bytes)
E0817 02:04:32.780365196 29 call.cc:1933] assertion failed: grpc_cq_begin_op(call->cq, notify_tag)

[stale]

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or other activity occurs. Thank you for your contributions.