Getting too_many_pings even after setting --grpc-keepalive-min-time

[szajbus]

Hi,

I am using a client that sends pings to etcd server periodically - every 10s, which is quite aggressive.

GRPC server used by etcd implements a keep alive policy as a protection against the clients that ping too often. I believe it allows 2 pings in 2 hours by default.

The etcd's documentation states that this setting can be controlled via --grpc-keepalive-min-time configuration option, which is set to 5s by default:

--grpc-keepalive-min-time '5s'
  Minimum duration interval that a client should wait before pinging server.

However, when my client sends pings every 10s, it receives exactly 3 pongs and then on 4th ping, the server responds with too_many_pings, which is exactly what would happen if the GRPC server used its own defaults, not the values provided by etcd.

I'd appreciate any help getting it to work.

I tried setting --grpc-keepalive-min-time option from command line as well as adding it to config file, but it doesn't seem to have any effect, so I am either doing something wrong or I don't understand how this setting is supposed to work.

[jmhbnz]

Hey @szajbus - Thanks for your question. Can you please confirm the full config you are using for etcd server and any other info that will help us recreate your scenario easily.

[szajbus]

Hey @jmhbnz, thank you for taking time for this.

I'm using etcd installed locally with homebrew (but also tried running in a container on a linux host).

$ etcd --version
etcd Version: 3.5.13
Git SHA: c9063a0dc
Go Version: go1.22.1
Go OS/Arch: darwin/arm64

Starting it like this:

$ etcd --grpc-keepalive-min-time 1s --log-level debug

Here's a minimal script that I was able to produce using Elixir and mint http/2 client: gist

The output of the script:

$ elixir etcd-ping.exs
2024-04-09 15:01:49.386066Z Connected
2024-04-09 15:01:49.387569Z Ping
2024-04-09 15:01:49.888848Z Pong
2024-04-09 15:01:54.889700Z Ping
2024-04-09 15:01:55.390817Z Pong
2024-04-09 15:02:00.391694Z Ping
2024-04-09 15:02:00.892780Z Pong
2024-04-09 15:02:05.893694Z Ping
2024-04-09 15:02:06.420249Z Error: %Mint.HTTPError{reason: {:server_closed_connection, :enhance_your_calm, "too_many_pings"}, module: Mint.HTTP2}
2024-04-09 15:02:11.422972Z Reconnecting
2024-04-09 15:02:11.426004Z Connected
2024-04-09 15:02:11.426080Z Ping
2024-04-09 15:02:11.926801Z Pong
2024-04-09 15:02:16.927669Z Ping
2024-04-09 15:02:17.428741Z Pong
2024-04-09 15:02:22.429674Z Ping
2024-04-09 15:02:22.930763Z Pong
2024-04-09 15:02:27.931979Z Ping
2024-04-09 15:02:28.432912Z Error: %Mint.HTTPError{reason: {:server_closed_connection, :enhance_your_calm, "too_many_pings"}, module: Mint.HTTP2}
^C

And etcd log:

{"level":"info","ts":"2024-04-09T17:04:23.896152+0200","caller":"zapgrpc/zapgrpc.go:174","msg":"[transport] [server-transport 0x1400013c1a0] loopyWriter exiting with error: second GOAWAY written and no active streams left to process"}
{"level":"info","ts":"2024-04-09T17:04:23.896329+0200","caller":"zapgrpc/zapgrpc.go:174","msg":"[transport] [server-transport 0x1400013c1a0] Closing: read tcp 127.0.0.1:2379->127.0.0.1:52554: use of closed network connection"}
{"level":"info","ts":"2024-04-09T17:04:23.896402+0200","caller":"zapgrpc/zapgrpc.go:174","msg":"[transport] [server-transport 0x1400013c1a0] Error closing underlying net.Conn during Close: close tcp 127.0.0.1:2379->127.0.0.1:52554: use of closed network connection"}
{"level":"info","ts":"2024-04-09T17:04:45.92601+0200","caller":"zapgrpc/zapgrpc.go:174","msg":"[transport] [server-transport 0x1400029c340] loopyWriter exiting with error: second GOAWAY written and no active streams left to process"}
{"level":"info","ts":"2024-04-09T17:04:45.926315+0200","caller":"zapgrpc/zapgrpc.go:174","msg":"[transport] [server-transport 0x1400029c340] Closing: read tcp 127.0.0.1:2379->127.0.0.1:52567: use of closed network connection"}
{"level":"info","ts":"2024-04-09T17:04:45.926398+0200","caller":"zapgrpc/zapgrpc.go:174","msg":"[transport] [server-transport 0x1400029c340] Error closing underlying net.Conn during Close: close tcp 127.0.0.1:2379->127.0.0.1:52567: use of closed network connection"}