client.rb

require 'logger'
require 'grpc'
require_relative 'helloworld_services_pb'

module RubyLogger
  def logger
    Logger.new(STDOUT, level: :debug)
  end
end
GRPC.extend(RubyLogger)

stub = Helloworld::Greeter::Stub.new('localhost:8000', :this_channel_is_insecure)
message = stub.say_hello(Helloworld::HelloRequest.new(name: 'ganmacs')).message
p "Greeting: #{message}"

client2.rb

require 'logger'
require 'grpc'
require 'grpc/health/checker'

module RubyLogger
  def logger
    Logger.new(STDOUT, level: :debug)
  end
end
GRPC.extend(RubyLogger)

stub = Grpc::Health::V1::Health::Stub.new('127.0.0.1:8000', :this_channel_is_insecure)
p stub.check(Grpc::Health::V1::HealthCheckRequest.new(service: 'test-app'))

result.log

envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:183] initializing epoch 0 (hot restart version=10.200.16384.127.options=capacity=16384, num_slots=8209 hash=228984379728933363 size=2654312)
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:185] statically linked extensions:
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:187]   access_loggers: envoy.file_access_log,envoy.http_grpc_access_log
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:190]   filters.http: envoy.buffer,envoy.cors,envoy.ext_authz,envoy.fault,envoy.filters.http.header_to_metadata,envoy.filters.http.jwt_authn,envoy.filters.http.rbac,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
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:193]   filters.listener: envoy.listener.original_dst,envoy.listener.proxy_protocol,envoy.listener.tls_inspector
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:196]   filters.network: envoy.client_ssl_auth,envoy.echo,envoy.ext_authz,envoy.filters.network.thrift_proxy,envoy.http_connection_manager,envoy.mongo_proxy,envoy.ratelimit,envoy.redis_proxy,envoy.tcp_proxy
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:198]   stat_sinks: envoy.dog_statsd,envoy.metrics_service,envoy.stat_sinks.hystrix,envoy.statsd
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:200]   tracers: envoy.dynamic.ot,envoy.lightstep,envoy.zipkin
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:203]   transport_sockets.downstream: envoy.transport_sockets.capture,raw_buffer,tls
envoy_1  | [2018-08-29 10:18:34.424][6][info][main] source/server/server.cc:206]   transport_sockets.upstream: envoy.transport_sockets.capture,raw_buffer,tls
envoy_1  | [2018-08-29 10:18:34.427][6][debug][main] source/server/server.cc:234] admin address: 0.0.0.0:8001
envoy_1  | [2018-08-29 10:18:34.430][6][info][config] source/server/configuration_impl.cc:50] loading 0 static secret(s)
envoy_1  | [2018-08-29 10:18:34.430][9][debug][grpc] source/common/grpc/google_async_client_impl.cc:39] completionThread running
envoy_1  | [2018-08-29 10:18:34.431][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:707] adding TLS initial cluster check-grpc
envoy_1  | [2018-08-29 10:18:34.431][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:707] adding TLS initial cluster hello-grpc
envoy_1  | [2018-08-29 10:18:34.431][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app
envoy_1  | [2018-08-29 10:18:34.432][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 5000 milliseconds
envoy_1  | [2018-08-29 10:18:34.432][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:61] cm init: adding: cluster=check-grpc primary=1 secondary=0
envoy_1  | [2018-08-29 10:18:34.432][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app2
envoy_1  | [2018-08-29 10:18:34.433][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 4687 milliseconds
envoy_1  | [2018-08-29 10:18:34.433][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:61] cm init: adding: cluster=hello-grpc primary=2 secondary=0
envoy_1  | [2018-08-29 10:18:34.433][6][info][config] source/server/configuration_impl.cc:60] loading 1 listener(s)
envoy_1  | [2018-08-29 10:18:34.433][6][debug][config] source/server/configuration_impl.cc:62] listener #0:
envoy_1  | [2018-08-29 10:18:34.433][6][debug][config] source/server/listener_manager_impl.cc:528] begin add/update listener: name=e9dc62d5-9307-4536-bd84-0d7530113937 hash=12660247465254500790
envoy_1  | [2018-08-29 10:18:34.433][6][debug][config] source/server/listener_manager_impl.cc:38]   filter #0:
envoy_1  | [2018-08-29 10:18:34.433][6][debug][config] source/server/listener_manager_impl.cc:39]     name: envoy.http_connection_manager
envoy_1  | [2018-08-29 10:18:34.433][6][debug][config] source/server/listener_manager_impl.cc:42]   config: {"stat_prefix":"ingress_http","route_config":{"virtual_hosts":[{"name":"backend","domains":["*"],"routes":[{"match":{"headers":[{"exact_match":"application/grpc","name":"content-type"}],"prefix":"/grpc.health.v1.Health/Check"},"route":{"retry_policy":{"per_try_timeout_ms":1000,"retry_on":"5xx,connect-failure,refused-stream,cancelled,deadline-exceeded,resource-exhausted","num_retries":3},"cluster":"check-grpc"}},{"match":{"headers":[{"exact_match":"application/grpc","name":"content-type"}],"prefix":"/helloworld.Greeter/SayHello"},"route":{"retry_policy":{"per_try_timeout_ms":1000,"retry_on":"5xx,connect-failure,refused-stream,cancelled,deadline-exceeded,resource-exhausted","num_retries":3},"cluster":"hello-grpc"}}]}],"name":"local_route"},"access_log":[{"config":{"path":"/dev/stdout"},"name":"envoy.file_access_log"}],"codec_type":"auto","http_filters":[{"config":{},"name":"envoy.router"}]}
envoy_1  | [2018-08-29 10:18:34.436][6][debug][config] source/extensions/filters/network/http_connection_manager/config.cc:278]     http filter #0
envoy_1  | [2018-08-29 10:18:34.436][6][debug][config] source/extensions/filters/network/http_connection_manager/config.cc:279]       name: envoy.router
envoy_1  | [2018-08-29 10:18:34.437][6][debug][config] source/extensions/filters/network/http_connection_manager/config.cc:283]     config: {}
envoy_1  | [2018-08-29 10:18:34.438][6][debug][config] source/server/listener_manager_impl.cc:414] add active listener: name=e9dc62d5-9307-4536-bd84-0d7530113937, hash=12660247465254500790, address=0.0.0.0:8000
envoy_1  | [2018-08-29 10:18:34.438][6][info][config] source/server/configuration_impl.cc:94] loading tracing configuration
envoy_1  | [2018-08-29 10:18:34.439][6][info][config] source/server/configuration_impl.cc:116] loading stats sink configuration
envoy_1  | [2018-08-29 10:18:34.441][6][info][main] source/server/server.cc:410] starting main dispatch loop
envoy_1  | [2018-08-29 10:18:34.441][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3124 milliseconds
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app2
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/upstream_impl.cc:1030] DNS hosts have changed for app2
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:844] membership update for TLS cluster hello-grpc
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:89] cm init: init complete: cluster=hello-grpc primary=1 secondary=0
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/upstream_impl.cc:1030] DNS hosts have changed for app
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:844] membership update for TLS cluster check-grpc
envoy_1  | [2018-08-29 10:18:34.442][6][debug][upstream] source/common/upstream/cluster_manager_impl.cc:89] cm init: init complete: cluster=check-grpc primary=0 secondary=0
envoy_1  | [2018-08-29 10:18:34.442][6][info][upstream] source/common/upstream/cluster_manager_impl.cc:133] cm init: all clusters initialized
envoy_1  | [2018-08-29 10:18:34.442][6][info][main] source/server/server.cc:390] all clusters initialized. initializing init manager
envoy_1  | [2018-08-29 10:18:34.442][6][info][config] source/server/listener_manager_impl.cc:798] all dependencies initialized. starting workers
envoy_1  | [2018-08-29 10:18:34.442][11][debug][main] source/server/worker_impl.cc:91] worker entering dispatch loop
envoy_1  | [2018-08-29 10:18:34.443][11][debug][upstream] source/common/upstream/cluster_manager_impl.cc:707] adding TLS initial cluster check-grpc
envoy_1  | [2018-08-29 10:18:34.443][11][debug][upstream] source/common/upstream/cluster_manager_impl.cc:707] adding TLS initial cluster hello-grpc
envoy_1  | [2018-08-29 10:18:34.443][11][debug][upstream] source/common/upstream/cluster_manager_impl.cc:844] membership update for TLS cluster hello-grpc
envoy_1  | [2018-08-29 10:18:34.443][11][debug][upstream] source/common/upstream/cluster_manager_impl.cc:844] membership update for TLS cluster check-grpc
envoy_1  | [2018-08-29 10:18:34.443][12][debug][main] source/server/worker_impl.cc:91] worker entering dispatch loop
envoy_1  | [2018-08-29 10:18:34.443][12][debug][upstream] source/common/upstream/cluster_manager_impl.cc:707] adding TLS initial cluster check-grpc
envoy_1  | [2018-08-29 10:18:34.443][12][debug][upstream] source/common/upstream/cluster_manager_impl.cc:707] adding TLS initial cluster hello-grpc
envoy_1  | [2018-08-29 10:18:34.443][12][debug][upstream] source/common/upstream/cluster_manager_impl.cc:844] membership update for TLS cluster hello-grpc
envoy_1  | [2018-08-29 10:18:34.443][12][debug][upstream] source/common/upstream/cluster_manager_impl.cc:844] membership update for TLS cluster check-grpc
envoy_1  | [2018-08-29 10:18:34.443][13][debug][grpc] source/common/grpc/google_async_client_impl.cc:39] completionThread running
envoy_1  | [2018-08-29 10:18:34.443][14][debug][grpc] source/common/grpc/google_async_client_impl.cc:39] completionThread running
envoy_1  | [2018-08-29 10:18:39.442][6][debug][main] source/server/server.cc:119] flushing stats
envoy_1  | [2018-08-29 10:18:39.442][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app2
envoy_1  | [2018-08-29 10:18:39.442][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3124 milliseconds
envoy_1  | [2018-08-29 10:18:39.442][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app
envoy_1  | [2018-08-29 10:18:39.442][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3124 milliseconds
envoy_1  | [2018-08-29 10:18:39.443][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3123 milliseconds
envoy_1  | [2018-08-29 10:18:39.444][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app
envoy_1  | [2018-08-29 10:18:39.445][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3123 milliseconds
envoy_1  | [2018-08-29 10:18:39.446][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 4061 milliseconds
envoy_1  | [2018-08-29 10:18:39.447][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app2
envoy_1  | [2018-08-29 10:18:44.433][6][debug][main] source/server/server.cc:119] flushing stats
envoy_1  | [2018-08-29 10:18:44.445][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app2
envoy_1  | [2018-08-29 10:18:44.445][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3124 milliseconds
envoy_1  | [2018-08-29 10:18:44.445][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app
envoy_1  | [2018-08-29 10:18:44.445][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3124 milliseconds
envoy_1  | [2018-08-29 10:18:44.447][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3122 milliseconds
envoy_1  | [2018-08-29 10:18:44.448][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3435 milliseconds
envoy_1  | [2018-08-29 10:18:44.450][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app2
envoy_1  | [2018-08-29 10:18:44.450][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3433 milliseconds
envoy_1  | [2018-08-29 10:18:44.451][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app
envoy_1  | [2018-08-29 10:18:47.749][11][debug][main] source/server/connection_handler_impl.cc:217] [C0] new connection
envoy_1  | [2018-08-29 10:18:47.749][11][debug][http2] source/common/http/http2/codec_impl.cc:621] [C0] setting stream-level initial window size to 268435456
envoy_1  | [2018-08-29 10:18:47.750][11][debug][http2] source/common/http/http2/codec_impl.cc:643] [C0] updating connection-level initial window size to 268435456
envoy_1  | [2018-08-29 10:18:47.750][11][debug][http] source/common/http/conn_manager_impl.cc:187] [C0] new stream
envoy_1  | [2018-08-29 10:18:47.750][11][debug][http] source/common/http/conn_manager_impl.cc:455] [C0][S8831859341876061626] request headers complete (end_stream=false):
envoy_1  | ':scheme', 'http'
envoy_1  | ':method', 'POST'
envoy_1  | ':authority', '127.0.0.1:8000'
envoy_1  | ':path', '/grpc.health.v1.Health/Check'
envoy_1  | 'te', 'trailers'
envoy_1  | 'content-type', 'application/grpc'
envoy_1  | 'user-agent', 'grpc-ruby/1.14.1 grpc-c/6.0.0 (osx; chttp2; gladiolus)'
envoy_1  | 'grpc-accept-encoding', 'identity,deflate,gzip'
envoy_1  | 'accept-encoding', 'identity,gzip'
envoy_1  |
envoy_1  | [2018-08-29 10:18:47.750][11][debug][router] source/common/router/router.cc:253] [C0][S8831859341876061626] cluster 'check-grpc' match for URL '/grpc.health.v1.Health/Check'
envoy_1  | [2018-08-29 10:18:47.750][11][debug][router] source/common/router/router.cc:304] [C0][S8831859341876061626] router decoding headers:
envoy_1  | ':scheme', 'http'
envoy_1  | ':method', 'POST'
envoy_1  | ':authority', '127.0.0.1:8000'
envoy_1  | ':path', '/grpc.health.v1.Health/Check'
envoy_1  | 'te', 'trailers'
envoy_1  | 'content-type', 'application/grpc'
envoy_1  | 'user-agent', 'grpc-ruby/1.14.1 grpc-c/6.0.0 (osx; chttp2; gladiolus)'
envoy_1  | 'grpc-accept-encoding', 'identity,deflate,gzip'
envoy_1  | 'accept-encoding', 'identity,gzip'
envoy_1  | 'x-forwarded-proto', 'http'
envoy_1  | 'x-request-id', 'c593c879-e2ed-4436-996e-7377fc65b355'
envoy_1  | 'x-envoy-expected-rq-timeout-ms', '15000'
envoy_1  |
envoy_1  | [2018-08-29 10:18:47.750][11][debug][client] source/common/http/codec_client.cc:25] [C1] connecting
envoy_1  | [2018-08-29 10:18:47.750][11][debug][connection] source/common/network/connection_impl.cc:570] [C1] connecting to 172.22.0.3:8000
envoy_1  | [2018-08-29 10:18:47.751][11][debug][connection] source/common/network/connection_impl.cc:579] [C1] connection in progress
envoy_1  | [2018-08-29 10:18:47.751][11][debug][http2] source/common/http/http2/codec_impl.cc:621] [C1] setting stream-level initial window size to 268435456
envoy_1  | [2018-08-29 10:18:47.751][11][debug][http2] source/common/http/http2/codec_impl.cc:643] [C1] updating connection-level initial window size to 268435456
envoy_1  | [2018-08-29 10:18:47.751][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C1] creating stream
envoy_1  | [2018-08-29 10:18:47.751][11][debug][router] source/common/router/router.cc:972] [C0][S8831859341876061626] pool ready
envoy_1  | [2018-08-29 10:18:47.751][11][debug][http] source/common/http/conn_manager_impl.cc:790] [C0][S8831859341876061626] request end stream
envoy_1  | [2018-08-29 10:18:47.751][11][debug][connection] source/common/network/connection_impl.cc:466] [C1] connected
envoy_1  | [2018-08-29 10:18:47.751][11][debug][client] source/common/http/codec_client.cc:63] [C1] connected
envoy_1  | [2018-08-29 10:18:47.756][11][debug][client] source/common/http/codec_client.cc:94] [C1] response complete
envoy_1  | [2018-08-29 10:18:47.756][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C1] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:18:47.756][11][debug][router] source/common/router/router.cc:584] [C0][S8831859341876061626] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:18:47.756][11][debug][router] source/common/router/router.cc:737] [C0][S8831859341876061626] performing retry
envoy_1  | [2018-08-29 10:18:47.756][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C1] stream closed: 0
envoy_1  | [2018-08-29 10:18:47.768][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C1] creating stream
envoy_1  | [2018-08-29 10:18:47.769][11][debug][router] source/common/router/router.cc:972] [C0][S8831859341876061626] pool ready
envoy_1  | [2018-08-29 10:18:47.769][11][debug][client] source/common/http/codec_client.cc:94] [C1] response complete
envoy_1  | [2018-08-29 10:18:47.769][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C1] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:18:47.769][11][debug][router] source/common/router/router.cc:584] [C0][S8831859341876061626] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:18:47.769][11][debug][router] source/common/router/router.cc:737] [C0][S8831859341876061626] performing retry
envoy_1  | [2018-08-29 10:18:47.769][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C1] stream closed: 0
envoy_1  | [2018-08-29 10:18:47.774][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C1] creating stream
envoy_1  | [2018-08-29 10:18:47.774][11][debug][router] source/common/router/router.cc:972] [C0][S8831859341876061626] pool ready
envoy_1  | [2018-08-29 10:18:47.775][11][debug][client] source/common/http/codec_client.cc:94] [C1] response complete
envoy_1  | [2018-08-29 10:18:47.775][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C1] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:18:47.775][11][debug][router] source/common/router/router.cc:584] [C0][S8831859341876061626] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:18:47.775][11][debug][router] source/common/router/router.cc:737] [C0][S8831859341876061626] performing retry
envoy_1  | [2018-08-29 10:18:47.775][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C1] stream closed: 0
envoy_1  | [2018-08-29 10:18:47.885][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C1] creating stream
envoy_1  | [2018-08-29 10:18:47.885][11][debug][router] source/common/router/router.cc:972] [C0][S8831859341876061626] pool ready
envoy_1  | [2018-08-29 10:18:47.886][11][debug][client] source/common/http/codec_client.cc:94] [C1] response complete
envoy_1  | [2018-08-29 10:18:47.886][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C1] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:18:47.886][11][debug][router] source/common/router/router.cc:584] [C0][S8831859341876061626] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:18:47.886][11][debug][http] source/common/http/conn_manager_impl.cc:981] [C0][S8831859341876061626] encoding headers via codec (end_stream=true):
envoy_1  | ':status', '200'
envoy_1  | 'content-type', 'application/grpc'
envoy_1  | 'grpc-status', '8'
envoy_1  | 'grpc-message', 'No free threads in thread pool'
envoy_1  | 'x-envoy-upstream-service-time', '134'
envoy_1  | 'date', 'Wed, 29 Aug 2018 10:18:47 GMT'
envoy_1  | 'server', 'envoy'
envoy_1  |
envoy_1  | [2018-08-29 10:18:47.886][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C0] stream closed: 0
envoy_1  | [2018-08-29 10:18:47.886][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C1] stream closed: 0
envoy_1  | [2018-08-29T10:18:47.750Z] "POST /grpc.health.v1.Health/Check HTTP/2" 200 - 15 0 136 134 "-" "grpc-ruby/1.14.1 grpc-c/6.0.0 (osx; chttp2; gladiolus)" "c593c879-e2ed-4436-996e-7377fc65b355" "127.0.0.1:8000" "172.22.0.3:8000"
envoy_1  | [2018-08-29 10:18:47.894][11][debug][connection] source/common/network/connection_impl.cc:451] [C0] remote close
envoy_1  | [2018-08-29 10:18:47.894][11][debug][connection] source/common/network/connection_impl.cc:133] [C0] closing socket: 0
envoy_1  | [2018-08-29 10:18:47.895][11][debug][main] source/server/connection_handler_impl.cc:50] [C0] adding to cleanup list
envoy_1  | [2018-08-29 10:18:49.435][6][debug][main] source/server/server.cc:119] flushing stats
envoy_1  | [2018-08-29 10:18:49.447][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app
envoy_1  | [2018-08-29 10:18:49.448][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3435 milliseconds
envoy_1  | [2018-08-29 10:18:49.452][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app2
envoy_1  | [2018-08-29 10:18:49.458][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3426 milliseconds
envoy_1  | [2018-08-29 10:18:49.465][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3750 milliseconds
envoy_1  | [2018-08-29 10:18:49.468][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app2
envoy_1  | [2018-08-29 10:18:49.470][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app
envoy_1  | [2018-08-29 10:18:54.436][6][debug][main] source/server/server.cc:119] flushing stats
envoy_1  | [2018-08-29 10:18:54.468][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app
envoy_1  | [2018-08-29 10:18:54.474][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 4058 milliseconds
envoy_1  | [2018-08-29 10:18:54.484][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app2
envoy_1  | [2018-08-29 10:18:54.490][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3432 milliseconds
envoy_1  | [2018-08-29 10:18:54.491][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3431 milliseconds
envoy_1  | [2018-08-29 10:18:54.494][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 2812 milliseconds
envoy_1  | [2018-08-29 10:18:54.494][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app
envoy_1  | [2018-08-29 10:18:54.494][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 2812 milliseconds
envoy_1  | [2018-08-29 10:18:54.499][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app2
envoy_1  | [2018-08-29 10:18:59.411][6][debug][main] source/server/server.cc:119] flushing stats
envoy_1  | [2018-08-29 10:18:59.458][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app
envoy_1  | [2018-08-29 10:18:59.459][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 3750 milliseconds
envoy_1  | [2018-08-29 10:18:59.459][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 2812 milliseconds
envoy_1  | [2018-08-29 10:18:59.460][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app
envoy_1  | [2018-08-29 10:18:59.475][6][debug][upstream] source/common/upstream/upstream_impl.cc:1004] starting async DNS resolution for app2
envoy_1  | [2018-08-29 10:18:59.476][6][debug][upstream] source/common/network/dns_impl.cc:147] Setting DNS resolution timer for 5000 milliseconds
envoy_1  | [2018-08-29 10:18:59.477][6][debug][upstream] source/common/upstream/upstream_impl.cc:1011] async DNS resolution complete for app2
envoy_1  | [2018-08-29 10:19:01.020][11][debug][main] source/server/connection_handler_impl.cc:217] [C2] new connection
envoy_1  | [2018-08-29 10:19:01.020][11][debug][http2] source/common/http/http2/codec_impl.cc:621] [C2] setting stream-level initial window size to 268435456
envoy_1  | [2018-08-29 10:19:01.021][11][debug][http2] source/common/http/http2/codec_impl.cc:643] [C2] updating connection-level initial window size to 268435456
envoy_1  | [2018-08-29 10:19:01.021][11][debug][http] source/common/http/conn_manager_impl.cc:187] [C2] new stream
envoy_1  | [2018-08-29 10:19:01.021][11][debug][http] source/common/http/conn_manager_impl.cc:455] [C2][S9063346722714130599] request headers complete (end_stream=false):
envoy_1  | ':scheme', 'http'
envoy_1  | ':method', 'POST'
envoy_1  | ':authority', 'localhost:8000'
envoy_1  | ':path', '/helloworld.Greeter/SayHello'
envoy_1  | 'te', 'trailers'
envoy_1  | 'content-type', 'application/grpc'
envoy_1  | 'user-agent', 'grpc-ruby/1.14.1 grpc-c/6.0.0 (osx; chttp2; gladiolus)'
envoy_1  | 'grpc-accept-encoding', 'identity,deflate,gzip'
envoy_1  | 'accept-encoding', 'identity,gzip'
envoy_1  |
envoy_1  | [2018-08-29 10:19:01.021][11][debug][router] source/common/router/router.cc:253] [C2][S9063346722714130599] cluster 'hello-grpc' match for URL '/helloworld.Greeter/SayHello'
envoy_1  | [2018-08-29 10:19:01.022][11][debug][router] source/common/router/router.cc:304] [C2][S9063346722714130599] router decoding headers:
envoy_1  | ':scheme', 'http'
envoy_1  | ':method', 'POST'
envoy_1  | ':authority', 'localhost:8000'
envoy_1  | ':path', '/helloworld.Greeter/SayHello'
envoy_1  | 'te', 'trailers'
envoy_1  | 'content-type', 'application/grpc'
envoy_1  | 'user-agent', 'grpc-ruby/1.14.1 grpc-c/6.0.0 (osx; chttp2; gladiolus)'
envoy_1  | 'grpc-accept-encoding', 'identity,deflate,gzip'
envoy_1  | 'accept-encoding', 'identity,gzip'
envoy_1  | 'x-forwarded-proto', 'http'
envoy_1  | 'x-request-id', '3406dbf5-bd07-4142-bf2f-e248f8e498e8'
envoy_1  | 'x-envoy-expected-rq-timeout-ms', '15000'
envoy_1  |
envoy_1  | [2018-08-29 10:19:01.022][11][debug][client] source/common/http/codec_client.cc:25] [C3] connecting
envoy_1  | [2018-08-29 10:19:01.022][11][debug][connection] source/common/network/connection_impl.cc:570] [C3] connecting to 172.22.0.2:8000
envoy_1  | [2018-08-29 10:19:01.023][11][debug][connection] source/common/network/connection_impl.cc:579] [C3] connection in progress
envoy_1  | [2018-08-29 10:19:01.023][11][debug][http2] source/common/http/http2/codec_impl.cc:621] [C3] setting stream-level initial window size to 268435456
envoy_1  | [2018-08-29 10:19:01.024][11][debug][http2] source/common/http/http2/codec_impl.cc:643] [C3] updating connection-level initial window size to 268435456
envoy_1  | [2018-08-29 10:19:01.024][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C3] creating stream
envoy_1  | [2018-08-29 10:19:01.024][11][debug][router] source/common/router/router.cc:972] [C2][S9063346722714130599] pool ready
envoy_1  | [2018-08-29 10:19:01.024][11][debug][http] source/common/http/conn_manager_impl.cc:790] [C2][S9063346722714130599] request end stream
envoy_1  | [2018-08-29 10:19:01.024][11][debug][connection] source/common/network/connection_impl.cc:466] [C3] connected
envoy_1  | [2018-08-29 10:19:01.024][11][debug][client] source/common/http/codec_client.cc:63] [C3] connected
app2_1   | 2018/08/29 10:19:01 Say hello
envoy_1  | [2018-08-29 10:19:01.053][11][debug][client] source/common/http/codec_client.cc:94] [C3] response complete
envoy_1  | [2018-08-29 10:19:01.053][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C3] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:19:01.053][11][debug][router] source/common/router/router.cc:584] [C2][S9063346722714130599] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:19:01.053][11][debug][router] source/common/router/router.cc:737] [C2][S9063346722714130599] performing retry
envoy_1  | [2018-08-29 10:19:01.053][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C3] stream closed: 0
envoy_1  | [2018-08-29 10:19:01.059][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C3] creating stream
envoy_1  | [2018-08-29 10:19:01.059][11][debug][router] source/common/router/router.cc:972] [C2][S9063346722714130599] pool ready
app2_1   | 2018/08/29 10:19:01 Say hello
envoy_1  | [2018-08-29 10:19:01.061][11][debug][client] source/common/http/codec_client.cc:94] [C3] response complete
envoy_1  | [2018-08-29 10:19:01.061][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C3] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:19:01.061][11][debug][router] source/common/router/router.cc:584] [C2][S9063346722714130599] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:19:01.061][11][debug][router] source/common/router/router.cc:737] [C2][S9063346722714130599] performing retry
envoy_1  | [2018-08-29 10:19:01.061][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C3] stream closed: 0
envoy_1  | [2018-08-29 10:19:01.133][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C3] creating stream
envoy_1  | [2018-08-29 10:19:01.133][11][debug][router] source/common/router/router.cc:972] [C2][S9063346722714130599] pool ready
envoy_1  | [2018-08-29 10:19:01.134][11][debug][client] source/common/http/codec_client.cc:94] [C3] response complete
envoy_1  | [2018-08-29 10:19:01.134][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C3] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:19:01.134][11][debug][router] source/common/router/router.cc:584] [C2][S9063346722714130599] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:19:01.134][11][debug][router] source/common/router/router.cc:737] [C2][S9063346722714130599] performing retry
envoy_1  | [2018-08-29 10:19:01.134][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C3] stream closed: 0
app2_1   | 2018/08/29 10:19:01 Say hello
envoy_1  | [2018-08-29 10:19:01.314][11][debug][pool] source/common/http/http2/conn_pool.cc:97] [C3] creating stream
envoy_1  | [2018-08-29 10:19:01.314][11][debug][router] source/common/router/router.cc:972] [C2][S9063346722714130599] pool ready
app2_1   | 2018/08/29 10:19:01 Say hello
envoy_1  | [2018-08-29 10:19:01.316][11][debug][client] source/common/http/codec_client.cc:94] [C3] response complete
envoy_1  | [2018-08-29 10:19:01.316][11][debug][pool] source/common/http/http2/conn_pool.cc:189] [C3] destroying stream: 0 remaining
envoy_1  | [2018-08-29 10:19:01.316][11][debug][router] source/common/router/router.cc:584] [C2][S9063346722714130599] upstream headers complete: end_stream=true
envoy_1  | [2018-08-29 10:19:01.317][11][debug][http] source/common/http/conn_manager_impl.cc:981] [C2][S9063346722714130599] encoding headers via codec (end_stream=true):
envoy_1  | ':status', '200'
envoy_1  | 'content-type', 'application/grpc'
envoy_1  | 'grpc-status', '4'
envoy_1  | 'grpc-message', 'always deadine exceeded'
envoy_1  | 'x-envoy-upstream-service-time', '292'
envoy_1  | 'date', 'Wed, 29 Aug 2018 10:19:00 GMT'
envoy_1  | 'server', 'envoy'
envoy_1  |
envoy_1  | [2018-08-29 10:19:01.317][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C2] stream closed: 0
envoy_1  | [2018-08-29 10:19:01.318][11][debug][http2] source/common/http/http2/codec_impl.cc:501] [C3] stream closed: 0
envoy_1  | [2018-08-29 10:19:01.320][11][debug][connection] source/common/network/connection_impl.cc:451] [C2] remote close
envoy_1  | [2018-08-29 10:19:01.320][11][debug][connection] source/common/network/connection_impl.cc:133] [C2] closing socket: 0
envoy_1  | [2018-08-29 10:19:01.320][11][debug][main] source/server/connection_handler_impl.cc:50] [C2] adding to cleanup list
Killing envoy-grpc_envoy_1  ... done
Killing envoy-grpc_app_1    ... done
Killing envoy-grpc_app2_1   ... done