Envoy: ADS Manager: upstream connect error or disconnect/reset before headers
Issue
ADS Management Server: upstream connect error or disconnect/reset before headers
Description:
I've starting writing a basic ADS management server in Golang. However, it seems that the envoy proxy is unable to establish a connection for a bidirectional stream with the ADS manager server. I'm using the Go envoy api commit https://github.com/envoyproxy/data-plane-api/commit/55833ac4e2008f760631392dd0a446325e4b7fef and the Envoy Proxy Docker image envoyproxy/envoy-alpine:5beff991a5f525c51f68d10e83b44637253d40f6[7/29/18] . The logs on the ADS Server seem to indicate that the initial http2 handshake fails. However, when I created a basic GRPC client is connects without issue.
Logs:
ADS GODEBUG: http2debug=2 Logs
2018/07/26 16:49:05 http2: Framer 0xc42013c000: wrote SETTINGS len=0
2018/07/26 16:49:17 http2: Framer 0xc42013c380: wrote SETTINGS len=0
2018/07/26 16:49:46 http2: Framer 0xc420202000: wrote SETTINGS len=0
2018/07/26 16:49:56 http2: Framer 0xc420260000: wrote SETTINGS len=0
2018/07/26 16:50:21 http2: Framer 0xc4202022a0: wrote SETTINGS len=0
2018/07/26 16:50:40 http2: Framer 0xc4202602a0: wrote SETTINGS len=0
2018/07/26 16:50:44 http2: Framer 0xc420202540: wrote SETTINGS len=0
...
Envoy Proxy Logs
[2018-07-26 16:44:38.401][10][debug][upstream] source/common/config/grpc_mux_impl.cc:38] Establishing new gRPC bidi stream for rpc StreamAggregatedResources(stream .envoy.api.v2.DiscoveryRequest) returns (stream .envoy.api.v2.DiscoveryResponse);
[2018-07-26 16:44:38.401][10][debug][router] source/common/router/router.cc:253] [C0][S2256890764864181315] cluster 'westeros-master' match for URL '/envoy.service.discovery.v2.AggregatedDiscoveryService/StreamAggregatedResources'
[2018-07-26 16:44:38.401][10][debug][router] source/common/router/router.cc:304] [C0][S2256890764864181315] router decoding headers:
':method', 'POST'
':path', '/envoy.service.discovery.v2.AggregatedDiscoveryService/StreamAggregatedResources'
':authority', 'westeros-master'
':scheme', 'http'
'te', 'trailers'
'content-type', 'application/grpc'
'x-envoy-internal', 'true'
'x-forwarded-for', '172.27.1.105'
[2018-07-26 16:44:38.401][10][debug][pool] source/common/http/http1/conn_pool.cc:79] creating a new connection
[2018-07-26 16:44:38.401][10][debug][client] source/common/http/codec_client.cc:25] [C6] connecting
[2018-07-26 16:44:38.401][10][debug][connection] source/common/network/connection_impl.cc:570] [C6] connecting to 172.27.1.225:9902
[2018-07-26 16:44:38.402][10][debug][connection] source/common/network/connection_impl.cc:579] [C6] connection in progress
[2018-07-26 16:44:38.402][10][debug][pool] source/common/http/http1/conn_pool.cc:105] queueing request due to no available connections
[2018-07-26 16:44:38.402][10][trace][upstream] source/common/config/grpc_mux_impl.cc:82] Sending DiscoveryRequest for type.googleapis.com/envoy.api.v2.Cluster: node {
id: "172.27.1.105"
cluster: "westeros-master"
build_version: "5beff991a5f525c51f68d10e83b44637253d40f6/1.8.0-dev/Clean/RELEASE"
}
type_url: "type.googleapis.com/envoy.api.v2.Cluster"
[2018-07-26 16:44:38.402][10][trace][router] source/common/router/router.cc:862] [C0][S2256890764864181315] buffering 146 bytes
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:389] [C6] socket event: 2
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:457] [C6] write ready
[2018-07-26 16:44:38.402][10][debug][connection] source/common/network/connection_impl.cc:466] [C6] connected
[2018-07-26 16:44:38.402][10][debug][client] source/common/http/codec_client.cc:63] [C6] connected
[2018-07-26 16:44:38.402][10][debug][pool] source/common/http/http1/conn_pool.cc:249] [C6] attaching to next request
[2018-07-26 16:44:38.402][10][debug][router] source/common/router/router.cc:972] [C0][S2256890764864181315] pool ready
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:326] [C6] writing 250 bytes, end_stream false
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:326] [C6] writing 152 bytes, end_stream false
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:457] [C6] write ready
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/raw_buffer_socket.cc:67] [C6] write returns: 402
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:389] [C6] socket event: 2
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:457] [C6] write ready
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:389] [C6] socket event: 3
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:457] [C6] write ready
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/connection_impl.cc:427] [C6] read ready
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/raw_buffer_socket.cc:23] [C6] read returns: 9
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/raw_buffer_socket.cc:23] [C6] read returns: -1
[2018-07-26 16:44:38.402][10][trace][connection] source/common/network/raw_buffer_socket.cc:31] [C6] read error: 104
[2018-07-26 16:44:38.402][10][trace][http] source/common/http/http1/codec_impl.cc:341] [C6] parsing 9 bytes
[2018-07-26 16:44:38.402][10][info][client] source/common/http/codec_client.cc:117] [C6] protocol error: http/1.1 protocol error: HPE_INVALID_CONSTANT
[2018-07-26 16:44:38.402][10][debug][connection] source/common/network/connection_impl.cc:98] [C6] closing data_to_write=0 type=1
[2018-07-26 16:44:38.402][10][debug][connection] source/common/network/connection_impl.cc:133] [C6] closing socket: 1
[2018-07-26 16:44:38.402][10][debug][client] source/common/http/codec_client.cc:81] [C6] disconnect. resetting 1 pending requests
[2018-07-26 16:44:38.402][10][debug][client] source/common/http/codec_client.cc:104] [C6] request reset
[2018-07-26 16:44:38.402][10][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-07-26 16:44:38.402][10][debug][router] source/common/router/router.cc:458] [C0][S2256890764864181315] upstream reset
[2018-07-26 16:44:38.402][10][debug][http] source/common/http/async_client_impl.cc:93] async http request response headers (end_stream=true):
':status', '200'
'content-type', 'application/grpc'
'grpc-status', '14'
'grpc-message', 'upstream connect error or disconnect/reset before headers'
[2018-07-26 16:44:38.402][10][warning][upstream] source/common/config/grpc_mux_impl.cc:240] gRPC config stream closed: 14, upstream connect error or disconnect/reset before headers
[2018-07-26 16:44:38.402][10][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=2)
[2018-07-26 16:44:38.402][10][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=3)
[2018-07-26 16:44:38.402][10][debug][pool] source/common/http/http1/conn_pool.cc:121] [C6] client disconnected
[2018-07-26 16:44:38.402][10][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=4)
[2018-07-26 16:44:38.402][10][debug][connection] source/common/network/connection_impl.cc:451] [C6] remote close
[2018-07-26 16:44:38.402][10][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=4)
Envoy Proxy GRPC Debug Logs
I0726 16:58:26.156164137 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:26.156189773 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=875038 next=9223372036854775807 tls_min=874038 glob_min=875038
I0726 16:58:26.156194468 12 timer_generic.cc:566] .. shard[0]->min_deadline = 875038
I0726 16:58:26.156198063 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:26.156200428 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 876037
I0726 16:58:26.156202919 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:26.156205575 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 875038 --> 876038, now=875038
I0726 16:58:26.156208650 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=876038
I0726 16:58:26.156211595 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:27.156182740 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:27.156223332 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=876038 next=9223372036854775807 tls_min=875038 glob_min=876038
I0726 16:58:27.156232331 12 timer_generic.cc:566] .. shard[0]->min_deadline = 876038
I0726 16:58:27.156238888 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:27.156244054 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 877037
I0726 16:58:27.156249274 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:27.156254867 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 876038 --> 877038, now=876038
I0726 16:58:27.156262910 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=877038
I0726 16:58:27.156267950 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:28.156167408 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:28.156194754 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=877038 next=9223372036854775807 tls_min=876038 glob_min=877038
I0726 16:58:28.156199121 12 timer_generic.cc:566] .. shard[0]->min_deadline = 877038
I0726 16:58:28.156202673 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:28.156205181 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 878037
I0726 16:58:28.156208038 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:28.156210594 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 877038 --> 878038, now=877038
I0726 16:58:28.156213781 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=878038
I0726 16:58:28.156216206 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:29.156156818 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:29.156183282 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=878038 next=9223372036854775807 tls_min=877038 glob_min=878038
I0726 16:58:29.156187925 12 timer_generic.cc:566] .. shard[0]->min_deadline = 878038
I0726 16:58:29.156191296 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:29.156193659 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 879037
I0726 16:58:29.156196155 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:29.156198869 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 878038 --> 879038, now=878038
I0726 16:58:29.156202106 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=879038
I0726 16:58:29.156204824 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:30.156159639 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:30.156185620 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=879038 next=9223372036854775807 tls_min=878038 glob_min=879038
I0726 16:58:30.156190286 12 timer_generic.cc:566] .. shard[0]->min_deadline = 879038
I0726 16:58:30.156193892 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:30.156196220 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 880037
I0726 16:58:30.156198646 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:30.156201280 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 879038 --> 880038, now=879038
I0726 16:58:30.156204419 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=880038
I0726 16:58:30.156206920 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:31.156182800 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:31.156222272 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=880038 next=9223372036854775807 tls_min=879038 glob_min=880038
I0726 16:58:31.156231194 12 timer_generic.cc:566] .. shard[0]->min_deadline = 880038
I0726 16:58:31.156237518 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:31.156242420 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 881037
I0726 16:58:31.156247647 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:31.156253173 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 880038 --> 881038, now=880038
I0726 16:58:31.156260947 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=881038
I0726 16:58:31.156266030 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:32.156162779 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:32.156199645 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=881038 next=9223372036854775807 tls_min=880038 glob_min=881038
I0726 16:58:32.156204346 12 timer_generic.cc:566] .. shard[0]->min_deadline = 881038
I0726 16:58:32.156207962 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:32.156210425 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 882037
I0726 16:58:32.156212854 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:32.156215313 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 881038 --> 882038, now=881038
I0726 16:58:32.156218411 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=882038
I0726 16:58:32.156220760 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:33.156158563 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:33.156183339 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=882038 next=9223372036854775807 tls_min=881038 glob_min=882038
I0726 16:58:33.156188243 12 timer_generic.cc:566] .. shard[0]->min_deadline = 882038
I0726 16:58:33.156191721 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:33.156194030 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 883037
I0726 16:58:33.156196425 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:33.156198998 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 882038 --> 883038, now=882038
I0726 16:58:33.156202283 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=883038
I0726 16:58:33.156204569 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:34.156186620 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:34.156224806 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=883038 next=9223372036854775807 tls_min=882038 glob_min=883038
I0726 16:58:34.156229302 12 timer_generic.cc:566] .. shard[0]->min_deadline = 883038
I0726 16:58:34.156232957 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:34.156235312 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 884037
I0726 16:58:34.156237896 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:34.156240363 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 883038 --> 884038, now=883038
I0726 16:58:34.156243501 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=884038
I0726 16:58:34.156245930 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:35.156157981 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:35.156184046 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=884038 next=9223372036854775807 tls_min=883038 glob_min=884038
I0726 16:58:35.156188900 12 timer_generic.cc:566] .. shard[0]->min_deadline = 884038
I0726 16:58:35.156192291 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:35.156194627 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 885037
I0726 16:58:35.156197076 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:35.156199493 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 884038 --> 885038, now=884038
I0726 16:58:35.156202890 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=885038
I0726 16:58:35.156205155 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:36.156160475 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:36.156190715 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=885038 next=9223372036854775807 tls_min=884038 glob_min=885038
I0726 16:58:36.156195607 12 timer_generic.cc:566] .. shard[0]->min_deadline = 885038
I0726 16:58:36.156199282 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:36.156202040 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 886037
I0726 16:58:36.156204604 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:36.156207120 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 885038 --> 886038, now=885038
I0726 16:58:36.156210373 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=886038
I0726 16:58:36.156212686 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:37.156159821 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:37.156184203 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=886038 next=9223372036854775807 tls_min=885038 glob_min=886038
I0726 16:58:37.156188510 12 timer_generic.cc:566] .. shard[0]->min_deadline = 886038
I0726 16:58:37.156191934 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:37.156194555 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 887037
I0726 16:58:37.156197126 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:37.156199739 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 886038 --> 887038, now=886038
I0726 16:58:37.156203025 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=887038
I0726 16:58:37.156205447 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:38.156169673 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:38.156209612 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=887038 next=9223372036854775807 tls_min=886038 glob_min=887038
I0726 16:58:38.156218456 12 timer_generic.cc:566] .. shard[0]->min_deadline = 887038
I0726 16:58:38.156224662 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:38.156229725 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 888037
I0726 16:58:38.156234825 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:38.156240288 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 887038 --> 888038, now=887038
I0726 16:58:38.156248274 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=888038
I0726 16:58:38.156253629 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:39.156169641 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:39.156194814 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=888038 next=9223372036854775807 tls_min=887038 glob_min=888038
I0726 16:58:39.156199304 12 timer_generic.cc:566] .. shard[0]->min_deadline = 888038
I0726 16:58:39.156202907 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:39.156205157 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 889037
I0726 16:58:39.156207652 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:39.156210204 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 888038 --> 889038, now=888038
I0726 16:58:39.156213328 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=889038
I0726 16:58:39.156215805 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:40.156162976 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:40.156189375 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=889038 next=9223372036854775807 tls_min=888038 glob_min=889038
I0726 16:58:40.156194282 12 timer_generic.cc:566] .. shard[0]->min_deadline = 889038
I0726 16:58:40.156197857 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:40.156200314 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 890037
I0726 16:58:40.156202864 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:40.156205407 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 889038 --> 890038, now=889038
I0726 16:58:40.156208450 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=890038
I0726 16:58:40.156211249 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:41.156163706 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:41.156189816 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=890038 next=9223372036854775807 tls_min=889038 glob_min=890038
I0726 16:58:41.156194451 12 timer_generic.cc:566] .. shard[0]->min_deadline = 890038
I0726 16:58:41.156198024 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:41.156200357 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 891037
I0726 16:58:41.156202743 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:41.156205666 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 890038 --> 891038, now=890038
I0726 16:58:41.156208740 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=891038
I0726 16:58:41.156211663 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:42.156159476 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:42.156185779 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=891038 next=9223372036854775807 tls_min=890038 glob_min=891038
I0726 16:58:42.156190879 12 timer_generic.cc:566] .. shard[0]->min_deadline = 891038
I0726 16:58:42.156194288 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:42.156196617 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 892037
I0726 16:58:42.156199011 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:42.156201595 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 891038 --> 892038, now=891038
I0726 16:58:42.156212707 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=892038
I0726 16:58:42.156215018 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:43.156189067 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:43.156214246 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=892038 next=9223372036854775807 tls_min=891038 glob_min=892038
I0726 16:58:43.156218830 12 timer_generic.cc:566] .. shard[0]->min_deadline = 892038
I0726 16:58:43.156222253 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:43.156224542 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 893037
I0726 16:58:43.156227112 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:43.156229650 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 892038 --> 893038, now=892038
I0726 16:58:43.156232811 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=893038
I0726 16:58:43.156235448 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:44.156162763 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:44.156189587 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=893038 next=9223372036854775807 tls_min=892038 glob_min=893038
I0726 16:58:44.156194373 12 timer_generic.cc:566] .. shard[0]->min_deadline = 893038
I0726 16:58:44.156198102 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:44.156200642 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 894037
I0726 16:58:44.156203077 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:44.156206067 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 893038 --> 894038, now=893038
I0726 16:58:44.156209123 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=894038
I0726 16:58:44.156211750 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:45.156158730 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:45.156184360 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=894038 next=9223372036854775807 tls_min=893038 glob_min=894038
I0726 16:58:45.156189356 12 timer_generic.cc:566] .. shard[0]->min_deadline = 894038
I0726 16:58:45.156192696 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:45.156195093 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 895037
I0726 16:58:45.156197704 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:45.156200262 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 894038 --> 895038, now=894038
I0726 16:58:45.156203612 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=895038
I0726 16:58:45.156206071 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:46.156180069 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:46.156220392 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=895038 next=9223372036854775807 tls_min=894038 glob_min=895038
I0726 16:58:46.156229731 12 timer_generic.cc:566] .. shard[0]->min_deadline = 895038
I0726 16:58:46.156236111 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:46.156241107 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 896037
I0726 16:58:46.156246320 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:46.156251764 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 895038 --> 896038, now=895038
I0726 16:58:46.156259467 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=896038
I0726 16:58:46.156264597 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:47.156157231 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:47.156183173 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=896038 next=9223372036854775807 tls_min=895038 glob_min=896038
I0726 16:58:47.156187593 12 timer_generic.cc:566] .. shard[0]->min_deadline = 896038
I0726 16:58:47.156191135 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:47.156193560 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 897037
I0726 16:58:47.156196053 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:47.156198712 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 896038 --> 897038, now=896038
I0726 16:58:47.156201987 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=897038
I0726 16:58:47.156204315 12 timer_manager.cc:175] sleep for a 1000 milliseconds
I0726 16:58:48.156191250 12 timer_manager.cc:190] wait ended: was_timed:1 kicked:0
I0726 16:58:48.156218771 12 timer_generic.cc:647] TIMER CHECK BEGIN: now=897038 next=9223372036854775807 tls_min=896038 glob_min=897038
I0726 16:58:48.156223618 12 timer_generic.cc:566] .. shard[0]->min_deadline = 897038
I0726 16:58:48.156227138 12 timer_generic.cc:503] .. shard[0]: heap_empty=true
I0726 16:58:48.156229461 12 timer_generic.cc:478] .. shard[0]->queue_deadline_cap --> 898037
I0726 16:58:48.156232035 12 timer_generic.cc:543] .. shard[0] popped 0
I0726 16:58:48.156234658 12 timer_generic.cc:583] .. result --> 1, shard[0]->min_deadline 897038 --> 898038, now=897038
I0726 16:58:48.156238164 12 timer_generic.cc:665] TIMER CHECK END: r=1; next=898038
I0726 16:58:48.156240564 12 timer_manager.cc:175] sleep for a 1000 milliseconds
question
zanes2016
All 3 comments
Was able to fix the issue. It seems to have been a problem with the configuration but i'm not sure what exactly was needed. I believe it had to do with how lb_policy and/or http2_protocol_options were defined.
Original (not working)
dynamic_resources:
cds_config: {ads: {}}
lds_config: {ads: {}}
ads_config:
api_type: GRPC
grpc_services:
envoy_grpc:
cluster_name: westeros-master
static_resources:
clusters:
- name: westeros-master
connect_timeout: { seconds: 5 }
type: STATIC #STRICT_DNS
hosts:
- socket_address:
address: 172.27.1.225
port_value: 9902
lb_policy: ROUND_ROBIN
http2_protocol_options: {}
"Correct" (working)
dynamic_resources:
cds_config: {ads: {}}
lds_config: {ads: {}}
ads_config:
api_type: GRPC
grpc_services:
envoy_grpc:
cluster_name: westeros-master
static_resources:
clusters:
- name: westeros-master
connect_timeout: { seconds: 1 }
type: STATIC #STRICT_DNS
lb_policy: ROUND_ROBIN
http2_protocol_options: {}
hosts:
- socket_address:
address: 172.27.1.225
port_value: 9902
http2_protocol_options: {}
FYI: the line http2_protocol_options: {} made the difference here. Seems that the mere presence of that field changes behavior.
abourget
on 18 Apr 2019
👍2
or more precisely, the fact that it needs to be specified in clusters attribute level, not in socket_address.
razvanphp
on 12 Sep 2019
Was this page helpful?
0 / 5 - 0 ratings
Related issues
rshriram
路
3Comments
hehe717
路
4Comments
justConfused
路
3Comments
jeremybaumont
路
3Comments
roelfdutoit
路
3Comments
Most helpful comment
FYI: the line
http2_protocol_options: {}made the difference here. Seems that the mere presence of that field changes behavior.