Excessive "gRPC config stream closed" log level #8270
Comments
|
xDS stream closure is harmless since the config is delivered in entirety (no deltas), but I don't know why pilot would be closing streams automatically every 5 minutes. |
|
Yeah we're consistently seeing this on all our proxies, on 5 minute intervals! |
|
Hey, can I rekindle this issue please because I seeming it correlate to 503s in a service.
|
|
If the stream is being closed exactly every 5 mins, it could be related to stream idle timeout. |
|
Hey folks, I'm tidying up old issues. If it's expected behaviour, I'm guessing it shouldn't be |
|
I have the same issue with istio 1.1.0-snapshot.3 .And I don't know the reason. |
|
It is just "log noise" but it is confusing to users so I have marked it My Ratings pod has been running fine for 22 hours and there are 262 of these messages in the logs. There is a Stack Overflow question showing a user who is troubleshooting a different problem is looking at this message https://stackoverflow.com/questions/54307216/istio-proxy-unable-to-connect-to-istio-pilot |
|
I'm getting pounded with this log noise as well, every istio-proxy container as part of any pod is spitting this warning out every 5 minutes. Is there any way to supress this warning if this is actually log noise? istio-proxy: [2019-03-06 14:44:33.157][18][warning][upstream] external/envoy/source/common/config/grpc_mux_impl.cc:240] gRPC config stream closed: 13, |
|
This message is coming from Envoy, not Istio. I verified that it is still in the latest Envoy source. It moved, but is there. https://github.com/envoyproxy/envoy/blob/master/source/common/config/grpc_stream.h#L92 The status 13 means internal error! I notice you are getting this message every 5 minutes. I am on 1.1 RC 2 and I am seeing it only every 30 minutes. Did something change in Istio or Envoy from 5 to 30 recently? That would give us an idea what is happening. |
|
I can take this and would be happy to send a PR to envoy, but it would be after 1.1. @esnible or anyone else, if you can get there sooner please take the bug and unassign me. |
|
not stalleeeee. I'm all in favour of reducing log noise to rekindling this |
|
On 1.1.2, this is still every 5 minutes for me. |
|
In my case, it happens every 27 ~ 32 minutes: $ kubectl -n istio-system logs -f --tail 100 istio-ingressgateway-7cd754f799-t7mv4
[2019-05-05 09:52:19.294][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 10:21:32.455][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 10:51:39.239][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 11:24:20.087][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 11:56:42.888][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 12:25:52.858][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 12:54:36.891][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 13:24:15.806][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 13:54:32.204][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 14:23:43.493][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 14:54:18.966][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 15:25:15.038][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 15:53:04.969][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 16:24:56.705][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 16:54:01.207][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 17:23:23.399][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 17:50:40.284][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 18:18:02.363][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 18:48:50.065][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 19:19:37.260][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 19:51:35.086][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 20:20:36.873][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 20:50:51.037][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 21:22:52.077][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 21:54:05.085][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 22:25:38.560][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 22:54:33.171][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 23:25:03.020][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-05 23:53:03.143][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-06 00:20:53.743][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-06 00:51:58.785][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,
[2019-05-06 01:19:39.861][23][warning][config] [bazel-out/k8-opt/bin/external/envoy/source/common/config/_virtual_includes/grpc_stream_lib/common/config/grpc_stream.h:86] gRPC config stream closed: 13,Http Request --> Kong --> Grpc client in K8S --> Grpc server in the same K8S cluster kong logs: 2019/05/05 18:25:09 [error] 21868#0: *7975 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 10.x.x.x, server: kong, request: "POST /grpc-client/graphql HTTP/1.0", upstream: "http:https://10.x.x.x:31380/graphql", host: "kong.x.com", referrer: "http:https://kong.x.com/grpc-client/graphql"I have traffic policies in ...
trafficPolicy:
connectionPool:
tcp:
connectTimeout: 30ms
tcpKeepalive:
interval: 75s
time: 2400s
...I don't know what exactly happens when the log shows, but it obviously interrupts communications between kong and istio, and never automatic recovery before you try. |
$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 16.04.5 LTS
Release: 16.04
Codename: xenial
$ kubectl version
Client Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.2", GitCommit:"cff46ab41ff0bb44d8584413b598ad8360ec1def", GitTreeState:"clean", BuildDate:"2019-01-10T23:35:51Z", GoVersion:"go1.11.4", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.2", GitCommit:"cff46ab41ff0bb44d8584413b598ad8360ec1def", GitTreeState:"clean", BuildDate:"2019-01-10T23:28:14Z", GoVersion:"go1.11.4", Compiler:"gc", Platform:"linux/amd64"}
$ helm version
Client: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"}
Server: &version.Version{SemVer:"v2.11.0", GitCommit:"2e55dbe1fdb5fdb96b75ff144a339489417b146b", GitTreeState:"clean"}
$ helm list
NAME REVISION UPDATED STATUS CHART APP VERSION NAMESPACE
istio 8 Tue Apr 30 11:07:18 2019 DEPLOYED istio-1.1.4 1.1.4 istio-system
istio-init 9 Tue Apr 30 11:07:15 2019 DEPLOYED istio-init-1.1.4 1.1.4 istio-system
$ istioctl version
version.BuildInfo{Version:"1.1.5", GitRevision:"9b6d31b74d1c0cc9358cc82d395b53f71393326b", User:"root", Host:"3e29fde4-6c3f-11e9-b00d-0a580a2c0205", GolangVersion:"go1.10.4", DockerHub:"docker.io/istio", BuildStatus:"Clean", GitTag:"1.1.4-10-g9b6d31b"} |
|
Can confirm we're seeing it in our logs every 30 minutes or so. |
|
Can confirm. every ~30minutes on 1.2.0 |
This one informs that a connection to Pilot has been closed by the Pilot: Caused by The parameter has been introduced in #10870 to improve rebalancing of clients to available Pilot instances:
The warning is harmless. |
|
The harmless message confuses operators because it appears at Although the log claims the message is from grpc_stream.h it is actually from source/common/config/grpc_mux_impl.cc and it ALWAYS logs at warning level onRemoteClose(). Would Envoy accept a PR that lowered the level to |
howardjohn
changed the title
|
@silentdai any idea if it is reasonable to just drop this to |
|
Not a grpc lawyer. An analogy is that HTTP protocol it's always worth noticing when the connection is closed by remote. Let me give it a try on envoy |
|
Confirm. every 30minutes on 1.2.2 |
|
I'm on 1.3.0 and I do have this error. The cluster was upgraded from 1.2.x to 1.3.0 when I started seeing this. I tried all sort of tcpdump to see is some of my streams were cancelled, but I can't find it. So it's clearly Envoy that is terminating (RESET) the TCP stream on both ends. As far as it goes, I see nothing in the Pilot logs, but I'm going to restart it with a debug image. |
|
Error on the Pilot side is : |
|
after I upgrade from istio.1.3.3 to 1.4.8, I started notice this warning log. I ever wonder if my process met with trouble, it misleaded me. |
|
@zackzhangkai each proxy should log that every 30 min by default. It closes the connexion to pilot and create a new one. You can safely ignore it in this case. |
Hey,
I'm unsure if this is something to be concerned about, but we're seeing gRPC stream close errors every 5 minutes in istio-proxy, since upgrading to 1.0.1
The proxies seem to be synced and up to date so i don't think it's causing any problems?
The text was updated successfully, but these errors were encountered: