consul
consul copied to clipboard
hashicorp
New WARN in 1.10.0 caused by shuffling the servers in the gRPC ClientConn pool
Note from @lkysow: I'm moving this to hashicorp/consul because the discuss post shows a user on EC2 also saw this error.
Overview of the Issue
New 1.10.0 on New K8s Cluster results in [WARN] agent: grpc: addrConn.createTransport failed to connect to {10.200.65.16:8300 0 consul-server-2.primary <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 10.200.65.16:8300: operation was canceled". Reconnecting...
These WARNS appear in both the server and clients.
Reproduction Steps
- When running helm install with the following
values.yml:
client:
enabled: true
grpc: true
connectInject:
aclBindingRuleSelector: serviceaccount.name!=default
default: false
enabled: true
metrics:
defaultEnableMerging: true
defaultEnabled: true
defaultMergedMetricsPort: 20100
defaultPrometheusScrapePath: /metrics
defaultPrometheusScrapePort: 20200
transparentProxy:
defaultEnabled: true
defaultOverwriteProbes: true
controller:
enabled: true
dns:
enabled: true
global:
acls:
createReplicationToken: true
manageSystemACLs: true
datacenter: primary
enabled: true
federation:
createFederationSecret: true
enabled: true
gossipEncryption:
secretKey: key
secretName: consul-gossip-encryption-key
image: hashicorp/consul:1.10.0
imageEnvoy: envoyproxy/envoy-alpine:v1.18.3
imageK8S: hashicorp/consul-k8s:0.26.0
logJSON: true
metrics:
agentMetricsRetentionTime: 1m
enableAgentMetrics: false
enableGatewayMetrics: true
enabled: true
name: consul
tls:
enableAutoEncrypt: true
enabled: true
httpsOnly: true
serverAdditionalDNSSANs:
- '*.consul'
- '*.svc.cluster.local'
- '*.my.customdomain.com'
verify: false
meshGateway:
enabled: true
service:
enabled: true
port: 443
type: LoadBalancer
wanAddress:
port: 443
source: Service
server:
bootstrapExpect: 5
connect: true
disruptionBudget:
enabled: true
maxUnavailable: 2
enabled: true
extraConfig: "{\n \"primary_datacenter\": \"primary\",\n \"performance\": {\n
\ \"raft_multiplier\": 3\n },\n \"dns_config\": {\n \"allow_stale\":
true,\n \"cache_max_age\": \"10s\",\n \"enable_additional_node_meta_txt\":
false,\n \"node_ttl\": \"1m\",\n \"soa\": {\n \"expire\": 86400,
\n \"min_ttl\": 30,\n \"refresh\": 3600,\n \"retry\": 600\n
\ },\n \"use_cache\": true\n}}"
replicas: 5
resources:
limits:
cpu: 500m
memory: 10Gi
requests:
cpu: 500m
memory: 10Gi
storage: 10Gi
updatePartition: 0
syncCatalog:
default: true
enabled: true
nodePortSyncType: ExternalFirst
syncClusterIPServices: true
toConsul: true
toK8S: true
ui:
enabled: true
metrics:
baseURL: http://mon-kube-prometheus-stack-prometheus.monitoring.svc.cluster.local
enabled: true
provider: prometheus
service:
enabled: true
type: NodePort
Expected behavior
WARNS should not be flooding the log and connections should be over 8301 not 8300
Environment details
If not already included, please provide the following:
-
consul-k8sversion:0 .26.0 -
consul-helmversion: 0.32.1 -
values.yamlused to deploy the helm chart: see above
Additional Context
It seems others are experiencing the same problem. https://discuss.hashicorp.com/t/grpc-warning-on-consul-1-10-0/26237
Hi, based on https://discuss.hashicorp.com/t/grpc-warning-on-consul-1-10-0/26237 it sounds like this issue is not specific to Kubernetes. I'm going to move this to hashicorp/consul.
Thank you for reporting this issue!
I was just running a Consul agent locally to debug a different issue and I noticed this problem happens at the same time as these 2 debug lines:
2021-07-13T20:26:20.707Z [DEBUG] agent.router.manager: Rebalanced servers, new active server: number_of_servers=2 active_server="a19bd98836ec.dc1 (Addr: tcp/172.20.0.2:8300) (DC: dc1)"
2021-07-13T20:26:20.707Z [WARN] agent: grpc: addrConn.createTransport failed to connect to {172.20.0.3:8300 0 0cc9dd0254a2.dc1 <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 172.20.0.3:8300: operation was canceled". Reconnecting...
2021-07-13T20:26:20.707Z [DEBUG] agent.router.manager: Rebalanced servers, new active server: number_of_servers=1 active_server="a19bd98836ec (Addr: tcp/172.20.0.2:8300) (DC: dc1)"
The problem seems to be that when we rebalance the servers the active transport is cancelled, which causes this error to be printed.
Is the issue here that the behavior is potentially incorrect, or that a common occurrence is erroneously categorized at WARN log level?
I've installed in a couple other locations with the same chart/values as above and in the same datacenter the warn messages are for the other consul-servers in the cluster. This occurs if the cluster is WAN federated or not, that doesn't appear to have an impact.
Currently, trying to track a couple of network issues I have been experiencing in consul 1.10.
I am trying to obtain more evidence but I deleted the 1.10 cluster and went back to 1.8.4 and it did not appear to have the WARN. Can this be ignored? Not sure yet.
seeing an exact mirror of of this problem on a small development cluster running on Raspberry PI 4's in a very basic configuration all running consul 1.10.1
the errors in my case are the server taking to itself,
eg: my 3 raft servers are made up of 3 nodes - called:
nog wesley jake
Node ID Address State Voter RaftProtocol wesley.no-dns.co.uk 5e8a186b-adb5-ebba-eeb4-e10656568adf 10.11.216.81:8300 leader true 3 nog.no-dns.co.uk 086a7491-bf09-c7e2-9151-74c817ffb74c 10.11.216.182:8300 follower true 3 jake.no-dns.co.uk aa37ec78-d438-8726-77e5-c5619dfb054a 10.11.216.234:8300 follower true 3
in nog's log
Jul 21 10:21:35 nog consul[5613]: 2021-07-21T10:21:35.048Z [WARN] agent: grpc: addrConn.createTransport failed to connect to {10.11.216.182:8300 0 nog.no-dns.co.uk.bathstable
the IP address 10.11.216.182 is actually the IP address of the host 'nog' - so the error is talking to itself
on the host 'jake' the log shows the same failure to connect to the host nog
Jul 21 10:17:17 jake consul[7781]: 2021-07-21T10:17:17.833Z [WARN] agent: grpc: addrConn.createTransport failed to connect to {10.11.216.182:8300 0 nog.no-dns.co.uk.bathstable
on the host wesley (leader)
Jul 21 10:19:19 wesley consul[15814]: 2021-07-21T10:19:19.779Z [WARN] agent: grpc: addrConn.createTransport failed to connect to {10.11.216.81:8300 0 wesley.no-dns.co.uk.bathstable
the 10.11.216.81 IP address it's failing to talk to is wesley - itself in this case.
Yeah, that is what I am seeing. It's the local cluster that is emitting these messages and FLOODING the logs
I see the same issue. Three node cluster running on VMs (Cent 8).
Consul v1.10.0 Revision 27de64da7 Running on Cent 8 VMs.
All three nodes sporadically spit out an error about connecting to one of the other master nodes.
agent: grpc: addrConn.createTransport failed to connect to {10.248.14.54:8300 0 consul02.c.blah.internal <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 10.248.14.54:8300: operation was canceled". Reconnecting...
I went ahead and did more installation tests.
I installed Consul 1.10.1 and Chart 0.32.1 and backed down the Consul and Chart version all the way to 1.8.4 and 0.26.0 as I am also experiencing other problems that are not related to this issue.
The WARNS appear in the latest 1.10.x versions and they are emitted in both the local datacenter as well as a federated environment using mesh gateways.
We are also seeing similar errors but there seems to be no issue with the cluster itself, we are running consul v1.10.1 on OL8 VM's.
@ikonia I'm running Consul on two Ras Pis, and ran into this issue couple of days ago as well. In case you haven't found a solution, I seems to find the cause for my issue.
I first noticed the inconsistency in member status shown on each Pi. As you can see from snippets below, Pi 1 seems to think that 02 is leaving the cluster, and 02 thinks it's still in it. So I restarted the consul service on 02 and that fixed the issue.
I think the problem was caused due to starting services on both Pis at the same time and the nodes didn't negotiate properly and somehow that caused this weird bug. I use Ansible for staging the node and manage configs on them, and whenever I changed the configs, it restarts the services at the same time on all nodes and that's not a good idea .... (duh ... ).
I'm not sure what you setup is, but maybe try to spin up the nodes one by one, which solved the problem for me.
raspi01:
Node Address Status Type Build Protocol DC Segment
raspi01.raspi 192.168.1.10:8302 alive server 1.10.1 2 raspi <all>
raspi02.raspi 192.168.1.11:8302 leaving server 1.10.1 2 raspi <all>
raspi02:
Node Address Status Type Build Protocol DC Segment
raspi01.raspi 192.168.1.10:8302 alive server 1.10.1 2 raspi <all>
raspi02.raspi 192.168.1.11:8302 alive server 1.10.1 2 raspi <all>
Restarts in the way you describe unfortunately does not solve the problem here. The clusters appear to be healthy otherwise, but this is flooding logs and I do not think we have received a response as to if the messages are indicative of an issue or is something that can be ignored and waiting for a patch.
I believe these messages can be ignored. We periodically rebalance servers in the connect pool, and it looks like doing so is causing gRPC to emit these warnings. It seems like gRPC is reconnecting after the rebalance, so likely we can move these messages to INFO instead of WARN, but we'll need to do more investigation to be sure.
we're having the same issue on ent version, will try to raise support ticket there
:100: this should be moved to an info level log, normal system behavior that doesn't result in any degradation and self heals should not be something we are warned about.
To clarify our current understanding of this: this is not a bug, but instead a misclassified log message (that shouldn't be WARN).
Per @dnephin:
I believe these messages can be ignored. We periodically rebalance servers in the connect pool, and it looks like doing so is causing gRPC to emit these warnings. It seems like gRPC is reconnecting after the rebalance, so likely we can move these messages to INFO instead of WARN, but we'll need to do more investigation to be sure.
In this case, the aforementioned "need to do more investigation" is about how to make the change to reduce verbosity, not about the cause or whether there's a bug. The change requires some investigation because the message is emitted by gRPC, not Consul.
If this log message was coming directly from Consul this would be much easier to fix. Unfortunately the log message is coming from a library (gRPC), which makes it a bit harder to fix.
I think we have two options for addressing this:
- change all gRPC WARN messages to INFO
- change how we modify the grpc ClientConnPool so that it does not warn
Option 1 is pretty safe, but I'm not sure if it fixes much. There will still be an INFO log message that is printed periodically. I guess it is slightly better to print this as an INFO than a WARN. The downside is that other gRPC WARN messages may not be visible enough in logs at INFO level.
Option 2 is much more involved, but is likely a safer long term fix. I believe the cause of this warning is this code: https://github.com/hashicorp/consul/blob/d20230fac1e89678ba6f5e26bad4d2fff99fe9f2/agent/grpc/resolver/resolver.go#L283-L287
If we trace those UpdateState calls, we'll see we can end up in the code that logs that warning. My rough understanding is that by updating the client conn state we are cancelling the dial operation, which prints this message. It may be that by calling UpdateState twice like this is what triggers the warning. Under normal operation I guess the dial would complete and we wouldn't see a warning. This also shows why we can't just hide the message, because if the dial operation was failing for some other reason, we'd want to know about it. The "further investigation" would be to see if we could remove the need to call UpdateState twice, and to confirm that is sufficient to prevent the warning.
We're seeing a pretty healthy amount of these messages as well across our clusters. Keeping our eyes on this.
Given the above, option 2 is definitely our preference. Not sure we want to even get a message in this case unless it's something to be concerned about
Can we ignore this error if everything is working as expected ? or Do we need to concern about this warning/error ?
Hey @nagender1005
Yes you can ignore this warning if everything is working as expected. Per earlier in this thread:
I believe these messages can be ignored. We periodically rebalance servers in the connect pool, and it looks like doing so is causing gRPC to emit these warnings. It seems like gRPC is reconnecting after the rebalance, so likely we can move these messages to INFO instead of WARN, but we'll need to do more investigation to be sure.
Hope this helps!
we are approaching this error being open for a year now ? is there a clear understanding of it and an plan to resolve it now, even if it's just a miss-classified error it should be easy to remediate and remove the confusion
Hey everyone, sorry for the inconvenience but as stated above, these WARNs are being emitted from the grpc library itself and we cannot easily suppress them without potentially hiding other valid WARN logs from grpc.
We are looking into Option 2 as outlined by @dnephin above but it is still an investigation in progress.
Consul v1.12.0 Revision 09a8cdb4
May 17 11:22:15 master1 consul[1095]: 2022-05-17T11:22:15.647+0300 [WARN] agent: [core]grpc: addrConn.createTransport failed to connect to {fsn1-10.44.0.4:8300 master3.fsn1
Consul v1.12.3 Revision 2308c75e
Jul 14 14:38:12 master2 consul[883807]: agent: [core]grpc: addrConn.createTransport failed to connect to {hel1-95.XX.XX.47:8300 master2.hel1
Jul 14 14:49:07 master2 consul[883807]: 2022-07-14T14:49:07.549+0300 [WARN] agent: [core]grpc: addrConn.createTransport failed to connect to {hel1-95.XX.XX.194:8300 master3.hel1