Requests go through after about 1000s (16-17 minutes)

[mju]

We have been debugging an issue where some gRPC requests take 16-17 minutes to go through. Below is a list of what we know.

• Eventually, the responses do come back successfully.
• Both client and server are written in Go.
• The server is a very simple gRPC server that has only a couple of unary endpoints.
• Both client and server don't have keepalive explicitly configured.
• On the client side, there is not a deadline configured with the context.
• waitForReady is set for the client.
• The client reuses a ClientConn object and never calls Close on it.
• The server is always up. During a 16-minute wait, the server has log to show that it serves other requests during that time frame. Same goes with the middle layers.
• During the 16-minute wait, we have health reports on the client-side that shows DNS resolution (net.DefaultResolver.LookupIPAddr(ctx, host)) worked at least 3 times and a TCP connection (DialContext(ctx, "tcp", net.JoinHostPort(host, port)) was able to be established.

Below are the layers in between the client and the server.

client -> (probably more layers) -> NLB -> Istio Ingress Gateway -> server

Below is a table of times that we observed in logs. Time is roughly in minutes.

step	time
client	t+0
Ingress	t+16*
server	t+16*

• The server always eventually gets the requests. It takes only about 60ms for the server to fully process a request. However, there isn't always a log entry in the Ingress log that corresponds to t+0 or t+16. In Ingress log, some requests took 20-30 minutes in total (data.istio_ingress.duration). Is it possible that gRPC keeps connections open under the hood?

After adding a deadline of 1 minute on the client side, we got back rpc error: code = DeadlineExceeded desc = context deadline exceeded. The program that calls the client retries 3 times. All 3 requests result in DeadlineExceeded. This is still with waitForReady set. In this case, the server never saw the requests. And the ingress log is always confusing.

Would you have any recommendations as to how to debug this further? If you have a potential scenario on your mind that could lead to this problem, I can try to simulate it with debug log on.

Questions:

https://pkg.go.dev/net#Dialer seems to state that gRPC by default sends a TCP keepalive probe once every 15 seconds. What happens when the probes result in no ACK?

[arjan-bal]

Hi @mju, from the deadline exceeded errors that you're seeing after setting a deadline of 1 minute, I suspect there is a connectivity failure between the client and server due to which gRPC is unable to create a transport within the 1 min deadline. You can enable gRPC logging by following https://github.com/grpc/grpc-go?tab=readme-ov-file#how-to-turn-on-logging

This would log an error similar to the following when gRPC client fails to connect to the server after each retry.

tlogger.go:116: INFO clientconn.go:1204 [core] [Channel #151 SubChannel #152]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:36999: connect: connection refused"  (t=+1.631605761s)

If you could share the gRPC logs from the failure period after scrubbing any sensitive information, I may be able to determine if there's a connectivity issue.

Regarding the question about Keepalive: What happens when the probes result in no ACK? Short Answer: If the server ACK for the ping frame is not received within the configured timeout, the transport will be closed.

gRPC Go has its its own HTTP/2 protocol implementation (we don't use the one from the Go standard library) and gRPC manages Keepalive on its own. Here is the user doc for the same: https://github.com/grpc/grpc-go/blob/master/Documentation/keepalive.md

This is the general doc for all gRPC languages: https://grpc.io/docs/guides/keepalive/

Client side implementation for keepalive: https://github.com/grpc/grpc-go/blob/7e12068baffd8e6328e99d901409cd49d0edebf6/internal/transport/http2_client.go#L1688

[mju]

I am trying to convince folks on my end to allow me to enable debug log. In the meantime, reading the gRPC code, I don't see how a TCP keepalive probe will be sent once every 15 seconds. Maybe I missed something. Given that we don't have client side keepalive set up, it seems the TCP configuration will be the system defaults.

It seems http2_client#dial(...) uses this code, which means there will be no TCP keepalive probes. And the system defaults will be used.

    // If negative, keep-alive probes are disabled.
    KeepAlive time.Duration

In our case, the defaults are

$ cat /proc/sys/net/ipv4/tcp_keepalive_intvl 
75
$ cat /proc/sys/net/ipv4/tcp_keepalive_probes 
9
$ cat /proc/sys/net/ipv4/tcp_keepalive_time 
7200

According to this link, this means

The first two parameters are expressed in seconds, and the last is the pure number. This means that the keepalive routines wait for two hours (7200 secs) before sending the first keepalive probe, and then resend it every 75 seconds. If no ACK response is received for nine consecutive times, the connection is marked as broken.

Given this information, how would gRPC behave given the set-up when the other side leaves abruptly (without sending anything such as an RST)?

[arjan-bal]

@mju, I discussed this with other maintainers, and based on the following line in gRFC (RFC for gRPC) for http/2 keepalive, we think the issue you're seeing may be caused by the absence of keepalives.

However, in the absence of writes the OS will not detect such failures and in the presence of writes detection can take many minutes.

So the suggestion is to configure http/2 keepalive using gRPC and see if it helps resolve your issue. Docs: https://github.com/grpc/grpc-go/blob/master/Documentation/keepalive.md

[mju]

I think so too. I wish there is a way to detect this easier. This is the best article we found on this topic. It deserves be inducted into the gRCP write-up hall of fame, in my opinion.

Below is how I created a set-up locally to force a 16m timeout. I modified the code in this example.

Server code where I removed the keepalive config to match our code:

type server struct {
        pb.UnimplementedEchoServer
}

func (s *server) UnaryEcho(ctx context.Context, req *pb.EchoRequest) (*pb.EchoResponse, error) {
        return &pb.EchoResponse{Message: req.Message}, nil
}

func main() {
        flag.Parse()

        address := fmt.Sprintf(":%v", *port)
        lis, err := net.Listen("tcp", address)
        if err != nil {
                log.Fatalf("failed to listen: %v", err)
        }

        s := grpc.NewServer(/*grpc.KeepaliveEnforcementPolicy(kaep), grpc.KeepaliveParams(kasp)*/)
        pb.RegisterEchoServer(s, &server{})

        if err := s.Serve(lis); err != nil {
                log.Fatalf("failed to serve: %v", err)
        }
}

Client code where keepalive is also removed and waitForReady is added to match our code. I reused a client in a loop where a request will be sent and the code sleeps a bit.

func main() {
        flag.Parse()

        conn, err := grpc.NewClient(
                *addr,
                grpc.WithTransportCredentials(insecure.NewCredentials()),
                //grpc.WithKeepaliveParams(kacp),
                grpc.WithDefaultCallOptions(grpc.WaitForReady(true)))
        if err != nil {
                log.Fatalf("did not connect: %v", err)
        }
        defer conn.Close()

        c := pb.NewEchoClient(conn)

        for i := 0; i < 3; i++ {
                ctx := context.Background()
                fmt.Println("Performing unary request")
                res, err := c.UnaryEcho(ctx, &pb.EchoRequest{Message: "keepalive demo"})
                if err != nil {
                        log.Fatalf("unexpected error from UnaryEcho: %v", err)
                }
                fmt.Println("RPC response:", res)
                time.Sleep(20 * time.Second)
        }

        select {} // Block forever; run with GODEBUG=http2debug=2 to observe ping frames and GOAWAYs due to idleness.
}

Start the server first then run the client. After the first request gets its response back, use the following iptable command to drop the packets whose src port is the server's port.

# To remove this rule s/-A/-D/
sudo iptables -A INPUT -p tcp --sport 50052 -i lo -j DROP

In a separate console, run sudo tcpdump -i lo port 50052 to see the packets going to the port.

This is from the client's console.

$ time go run main.go
Performing unary request
RPC response: message:"keepalive demo"     <--------- set up the iptable rule once you see this line.
Performing unary request

It times out after about 16m.

$ time go run main.go
Performing unary request
RPC response: message:"keepalive demo"
Performing unary request
2024/08/22 11:26:34 unexpected error from UnaryEcho: rpc error: code = Unavailable desc = error reading from server: read tcp 127.0.0.1:35658->127.0.0.1:50052: read: connection timed out
exit status 1

real    15m59.622s
user    0m0.849s
sys 0m0.344s

With the debug log and http2debug (GODEBUG=http2debug=2 GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=info):

Performing unary request
2024/08/22 11:58:15 http2: Framer 0xc000224000: wrote HEADERS flags=END_HEADERS stream=3 len=7
2024/08/22 11:58:15 http2: Framer 0xc000224000: wrote DATA flags=END_STREAM stream=3 len=21 data="\x00\x00\x00\x00\x10\n\x0ekeepalive demo"
2024/08/22 12:13:54 INFO: [transport] [client-transport 0xc000172480] Closing: connection error: desc = "error reading from server: read tcp 127.0.0.1:40590->127.0.0.1:50052: read: connection timed out"
2024/08/22 12:13:54 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE
2024/08/22 12:13:54 http2: Framer 0xc000224000: wrote GOAWAY len=33 LastStreamID=3 ErrCode=NO_ERROR Debug="client transport shutdown"
2024/08/22 12:13:54 INFO: [pick-first-lb] [pick-first-lb 0xc000112cf0] Received SubConn state update: 0xc000112d80, {ConnectivityState:IDLE ConnectionError:<nil>}
2024/08/22 12:13:54 INFO: [transport] [client-transport 0xc000172480] loopyWriter exiting with error: connection error: desc = "error reading from server: read tcp 127.0.0.1:40590->127.0.0.1:50052: read: connection timed out"
2024/08/22 12:13:54 INFO: [core] [Channel #1]Channel Connectivity change to IDLE
2024/08/22 12:13:54 unexpected error from UnaryEcho: rpc error: code = Unavailable desc = error reading from server: read tcp 127.0.0.1:40590->127.0.0.1:50052: read: connection timed out
exit status 1

real    16m0.202s
user    0m0.831s
sys 0m0.239s

In tcp dump, it tries to push for a few times than push followed by reset. I might missed the first few packets.

11:58:16.761677 IP localhost.50052 > localhost.40590: Flags [P.], seq 158:240, ack 253, win 512, options [nop,nop,TS val 3156222574 ecr 3156222542], length 82
11:58:17.565690 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156223378 ecr 3156201693], length 46
11:58:17.565711 IP localhost.50052 > localhost.40590: Flags [.], ack 253, win 512, options [nop,nop,TS val 3156223378 ecr 3156223378,nop,nop,sack 1 {207:253}], length 0
11:58:17.629680 IP localhost.50052 > localhost.40590: Flags [P.], seq 158:240, ack 253, win 512, options [nop,nop,TS val 3156223442 ecr 3156223378], length 82
11:58:19.229695 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156225042 ecr 3156201693], length 46
11:58:19.229722 IP localhost.50052 > localhost.40590: Flags [.], ack 253, win 512, options [nop,nop,TS val 3156225042 ecr 3156225042,nop,nop,sack 1 {207:253}], length 0
11:58:19.325754 IP localhost.50052 > localhost.40590: Flags [P.], seq 158:240, ack 253, win 512, options [nop,nop,TS val 3156225138 ecr 3156225042], length 82
11:58:22.521686 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156228334 ecr 3156201693], length 46
11:58:22.521716 IP localhost.50052 > localhost.40590: Flags [.], ack 253, win 512, options [nop,nop,TS val 3156228334 ecr 3156228334,nop,nop,sack 1 {207:253}], length 0
11:58:22.777755 IP localhost.50052 > localhost.40590: Flags [P.], seq 158:240, ack 253, win 512, options [nop,nop,TS val 3156228590 ecr 3156228334], length 82
11:58:29.181789 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156234994 ecr 3156201693], length 46
11:58:29.181811 IP localhost.50052 > localhost.40590: Flags [.], ack 253, win 512, options [nop,nop,TS val 3156234994 ecr 3156234994,nop,nop,sack 1 {207:253}], length 0
11:58:29.689733 IP localhost.50052 > localhost.40590: Flags [P.], seq 158:240, ack 253, win 512, options [nop,nop,TS val 3156235502 ecr 3156234994], length 82
11:58:42.489711 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156248302 ecr 3156201693], length 46
11:58:42.489737 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
11:59:10.137712 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156275950 ecr 3156201693], length 46
11:59:10.137740 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
12:00:03.385730 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156329198 ecr 3156201693], length 46
12:00:03.385765 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
12:01:49.882143 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156435694 ecr 3156201693], length 46
12:01:49.882178 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
12:03:50.714113 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156556526 ecr 3156201693], length 46
12:03:50.714148 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
12:05:51.546134 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156677358 ecr 3156201693], length 46
12:05:51.546145 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
12:07:52.378131 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156798190 ecr 3156201693], length 46
12:07:52.378168 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
12:09:53.209876 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3156919022 ecr 3156201693], length 46
12:09:53.209922 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0
12:11:54.041966 IP localhost.40590 > localhost.50052: Flags [P.], seq 207:253, ack 158, win 512, options [nop,nop,TS val 3157039854 ecr 3156201693], length 46
12:11:54.041980 IP localhost.50052 > localhost.40590: Flags [R], seq 2799068919, win 0, length 0

Then I changed the keep alive config on the client side to

var kacp = keepalive.ClientParameters{
        Timeout:             90 * time.Second,      // wait 1 second for ping ack before considering the connection dead
}

It did time out after about 1m30s

Performing unary request
2024/08/22 12:54:52 http2: Framer 0xc000218000: wrote HEADERS flags=END_HEADERS stream=3 len=7
2024/08/22 12:54:52 http2: Framer 0xc000218000: wrote DATA flags=END_STREAM stream=3 len=21 data="\x00\x00\x00\x00\x10\n\x0ekeepalive demo"
2024/08/22 12:54:52 http2: Framer 0xc000218000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2024/08/22 12:56:22 INFO: [transport] [client-transport 0xc000172480] Closing: connection error: desc = "keepalive ping failed to receive ACK within timeout"
2024/08/22 12:56:22 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE
2024/08/22 12:56:22 http2: Framer 0xc000218000: wrote GOAWAY len=33 LastStreamID=3 ErrCode=NO_ERROR Debug="client transport shutdown"
2024/08/22 12:56:22 INFO: [pick-first-lb] [pick-first-lb 0xc000112cf0] Received SubConn state update: 0xc000112d80, {ConnectivityState:IDLE ConnectionError:<nil>}
2024/08/22 12:56:22 INFO: [transport] [client-transport 0xc000172480] loopyWriter exiting with error: connection error: desc = "keepalive ping failed to receive ACK within timeout"
2024/08/22 12:56:22 INFO: [core] [Channel #1]Channel Connectivity change to IDLE
2024/08/22 12:56:22 unexpected error from UnaryEcho: rpc error: code = Unavailable desc = keepalive ping failed to receive ACK within timeout
exit status 1

real    1m51.344s
user    0m0.750s
sys 0m0.395s

TCP dump

12:54:47.869765 IP localhost.50052 > localhost.44972: Flags [.], ack 207, win 512, options [nop,nop,TS val 3159613682 ecr 3159598494], length 0
12:54:52.646177 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159618458 ecr 3159598450], length 63
12:54:52.646997 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159618459 ecr 3159618458], length 99
12:54:52.853967 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159618666 ecr 3159598450], length 63
12:54:52.853998 IP localhost.50052 > localhost.44972: Flags [.], ack 270, win 512, options [nop,nop,TS val 3159618666 ecr 3159618666,nop,nop,sack 1 {207:270}], length 0
12:54:52.857778 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159618670 ecr 3159618666], length 99
12:54:53.061705 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159618874 ecr 3159598450], length 63
12:54:53.061732 IP localhost.50052 > localhost.44972: Flags [.], ack 270, win 512, options [nop,nop,TS val 3159618874 ecr 3159618874,nop,nop,sack 1 {207:270}], length 0
12:54:53.074033 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159618886 ecr 3159618874], length 99
12:54:53.497761 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159619310 ecr 3159598450], length 63
12:54:53.497794 IP localhost.50052 > localhost.44972: Flags [.], ack 270, win 512, options [nop,nop,TS val 3159619310 ecr 3159619310,nop,nop,sack 1 {207:270}], length 0
12:54:53.501797 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159619314 ecr 3159619310], length 99
12:54:54.329761 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159620142 ecr 3159598450], length 63
12:54:54.329787 IP localhost.50052 > localhost.44972: Flags [.], ack 270, win 512, options [nop,nop,TS val 3159620142 ecr 3159620142,nop,nop,sack 1 {207:270}], length 0
12:54:54.365749 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159620178 ecr 3159620142], length 99
12:54:55.997716 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159621810 ecr 3159598450], length 63
12:54:55.997761 IP localhost.50052 > localhost.44972: Flags [.], ack 270, win 512, options [nop,nop,TS val 3159621810 ecr 3159621810,nop,nop,sack 1 {207:270}], length 0
12:54:56.057785 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159621870 ecr 3159621810], length 99
12:54:59.385781 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159625198 ecr 3159598450], length 63
12:54:59.385815 IP localhost.50052 > localhost.44972: Flags [.], ack 270, win 512, options [nop,nop,TS val 3159625198 ecr 3159625198,nop,nop,sack 1 {207:270}], length 0
12:54:59.645766 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159625458 ecr 3159625198], length 99
12:55:06.041784 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159631854 ecr 3159598450], length 63
12:55:06.041816 IP localhost.50052 > localhost.44972: Flags [.], ack 270, win 512, options [nop,nop,TS val 3159631854 ecr 3159631854,nop,nop,sack 1 {207:270}], length 0
12:55:06.554458 IP localhost.50052 > localhost.44972: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3159632366 ecr 3159631854], length 99
12:55:19.357801 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159645170 ecr 3159598450], length 63
12:55:19.357834 IP localhost.50052 > localhost.44972: Flags [R], seq 927493437, win 0, length 0
12:55:45.721790 IP localhost.44972 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3159671534 ecr 3159598450], length 63
12:55:45.721821 IP localhost.50052 > localhost.44972: Flags [R], seq 927493437, win 0, length 0
12:56:22.718454 IP localhost.44972 > localhost.50052: Flags [FP.], seq 270:312, ack 158, win 512, options [nop,nop,TS val 3159708530 ecr 3159598450], length 42
12:56:22.718498 IP localhost.50052 > localhost.44972: Flags [R], seq 927493437, win 0, length 0

[mju]

To prove that after keepalive detect a broken connection, it will timeout and reconnect, I modified the client to not fatal-exit on error.

        for i := 0; i < 3; i++ {
                ctx := context.Background()
                fmt.Println("Performing unary request")
                res, err := c.UnaryEcho(ctx, &pb.EchoRequest{Message: "keepalive demo"})
                if err != nil {
                        log.Printf("unexpected error from UnaryEcho: %v", err)
                }
                fmt.Println("RPC response:", res)
                time.Sleep(20 * time.Second)
        }

This is so that once we see the error unexpected error from UnaryEcho, we would be able to go and remove the iptable rule and observe the [S] flag (SYN) in tcpdump. It means under the hood, gRPC code tries to reconnect to the server.

RPC response: message:"keepalive demo"    ###### this is from the first request before we block the server packets.
2024/08/22 13:16:06 http2: Framer 0xc000232000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
Performing unary request
2024/08/22 13:16:26 http2: Framer 0xc000232000: wrote HEADERS flags=END_HEADERS stream=3 len=7
2024/08/22 13:16:26 http2: Framer 0xc000232000: wrote DATA flags=END_STREAM stream=3 len=21 data="\x00\x00\x00\x00\x10\n\x0ekeepalive demo"
2024/08/22 13:16:26 http2: Framer 0xc000232000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2024/08/22 13:17:56 INFO: [transport] [client-transport 0xc000172480] Closing: connection error: desc = "keepalive ping failed to receive ACK within timeout"                ##############  the keepalive timeout.  Now go and remove the iptable rule
2024/08/22 13:17:56 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE
2024/08/22 13:17:56 http2: Framer 0xc000232000: wrote GOAWAY len=33 LastStreamID=3 ErrCode=NO_ERROR Debug="client transport shutdown"
2024/08/22 13:17:56 INFO: [pick-first-lb] [pick-first-lb 0xc000110cf0] Received SubConn state update: 0xc000110d80, {ConnectivityState:IDLE ConnectionError:<nil>}
2024/08/22 13:17:56 INFO: [transport] [client-transport 0xc000172480] loopyWriter exiting with error: connection error: desc = "keepalive ping failed to receive ACK within timeout"
2024/08/22 13:17:56 INFO: [core] [Channel #1]Channel Connectivity change to IDLE
2024/08/22 13:17:56 unexpected error from UnaryEcho: rpc error: code = Unavailable desc = keepalive ping failed to receive ACK within timeout
RPC response: <nil>
2024/08/22 13:17:56 INFO: [core] [Channel #1]Resolver state updated: {
  "Addresses": [
    {
      "Addr": "127.0.0.1:50052",
      "ServerName": "",
      "Attributes": null,
      "BalancerAttributes": null,
      "Metadata": null
    }
  ],
  "Endpoints": [
    {
      "Addresses": [
        {
          "Addr": "127.0.0.1:50052",
          "ServerName": "",
          "Attributes": null,
          "BalancerAttributes": null,
          "Metadata": null
        }
      ],
      "Attributes": null
    }
  ],
  "ServiceConfig": null,
  "Attributes": null
} ()
2024/08/22 13:17:56 INFO: [pick-first-lb] [pick-first-lb 0xc000110cf0] Received new config {
  "shuffleAddressList": false
}, resolver state {
  "Addresses": [
    {
      "Addr": "127.0.0.1:50052",
      "ServerName": "",
      "Attributes": null,
      "BalancerAttributes": null,
      "Metadata": null
    }
  ],
  "Endpoints": [
    {
      "Addresses": [
        {
          "Addr": "127.0.0.1:50052",
          "ServerName": "",
          "Attributes": null,
          "BalancerAttributes": null,
          "Metadata": null
        }
      ],
      "Attributes": null
    }
  ],
  "ServiceConfig": null,
  "Attributes": null
}
2024/08/22 13:17:56 INFO: [core] [Channel #1 SubChannel #2]addrConn: updateAddrs addrs (1 of 1): [{Addr: "127.0.0.1:50052", ServerName: "", }]
Performing unary request
2024/08/22 13:18:16 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
2024/08/22 13:18:16 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address "127.0.0.1:50052" to connect
2024/08/22 13:18:16 INFO: [pick-first-lb] [pick-first-lb 0xc000110cf0] Received SubConn state update: 0xc000110d80, {ConnectivityState:CONNECTING ConnectionError:<nil>}
2024/08/22 13:18:16 INFO: [core] [Channel #1]Channel Connectivity change to CONNECTING
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: wrote SETTINGS len=0
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read SETTINGS len=6, settings: MAX_FRAME_SIZE=16384
2024/08/22 13:18:35 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to READY
2024/08/22 13:18:35 INFO: [pick-first-lb] [pick-first-lb 0xc000110cf0] Received SubConn state update: 0xc000110d80, {ConnectivityState:READY ConnectionError:<nil>}
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: wrote SETTINGS flags=ACK len=0
2024/08/22 13:18:35 INFO: [core] [Channel #1]Channel Connectivity change to READY
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read SETTINGS flags=ACK len=0
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: wrote HEADERS flags=END_HEADERS stream=1 len=78
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: wrote DATA flags=END_STREAM stream=1 len=21 data="\x00\x00\x00\x00\x10\n\x0ekeepalive demo"
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read WINDOW_UPDATE len=4 (conn) incr=21
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read HEADERS flags=END_HEADERS stream=1 len=14
2024/08/22 13:18:35 http2: decoded hpack field header field ":status" = "200"
2024/08/22 13:18:35 http2: decoded hpack field header field "content-type" = "application/grpc"
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read DATA stream=1 len=21 data="\x00\x00\x00\x00\x10\n\x0ekeepalive demo"
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: wrote WINDOW_UPDATE len=4 (conn) incr=21
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2024/08/22 13:18:35 http2: decoded hpack field header field "grpc-status" = "0"
2024/08/22 13:18:35 http2: decoded hpack field header field "grpc-message" = ""
RPC response: message:"keepalive demo"           ######### 3rd request went through.
2024/08/22 13:18:35 http2: Framer 0xc0002b6000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
^Csignal: interrupt

real    3m40.571s
user    0m0.805s
sys 0m0.328s

In tcpdump, we observed that it tried to do the 3 way handshaking (syn, syn/ack, ack) multiple time because i was slow with the iptable rule removal.

...
13:16:27.609760 IP localhost.50052 > localhost.57752: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3160913422 ecr 3160911896], length 99
13:16:29.305802 IP localhost.50052 > localhost.57752: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3160915118 ecr 3160911896], length 99
13:16:32.697983 IP localhost.50052 > localhost.57752: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3160918510 ecr 3160911896], length 99
13:16:39.609787 IP localhost.50052 > localhost.57752: Flags [P.], seq 158:257, ack 270, win 512, options [nop,nop,TS val 3160925422 ecr 3160911896], length 99
13:16:49.337823 IP localhost.57752 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3160935150 ecr 3160891890], length 63
13:16:49.337866 IP localhost.50052 > localhost.57752: Flags [R], seq 1717633208, win 0, length 0

13:17:44.633816 IP localhost.57752 > localhost.50052: Flags [P.], seq 207:270, ack 158, win 512, options [nop,nop,TS val 3160990446 ecr 3160891890], length 63
13:17:44.633857 IP localhost.50052 > localhost.57752: Flags [R], seq 1717633208, win 0, length 0
13:17:56.152716 IP localhost.57752 > localhost.50052: Flags [FP.], seq 270:312, ack 158, win 512, options [nop,nop,TS val 3161001965 ecr 3160891890], length 42
13:17:56.152771 IP localhost.50052 > localhost.57752: Flags [R], seq 1717633208, win 0, length 0

13:18:16.154240 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161021966 ecr 0,nop,wscale 7], length 0
13:18:16.154277 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161021966 ecr 3161021966,nop,wscale 7], length 0
13:18:17.178062 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161022990 ecr 0,nop,wscale 7], length 0
13:18:17.178090 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161022990 ecr 3161021966,nop,wscale 7], length 0
13:18:17.178096 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161022990 ecr 3161021966,nop,wscale 7], length 0
13:18:18.201779 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161024014 ecr 0,nop,wscale 7], length 0
13:18:18.201822 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161024014 ecr 3161021966,nop,wscale 7], length 0
13:18:19.226026 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161025038 ecr 0,nop,wscale 7], length 0
13:18:19.226041 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161025038 ecr 3161021966,nop,wscale 7], length 0
13:18:20.249979 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161026062 ecr 0,nop,wscale 7], length 0
13:18:20.250021 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161026062 ecr 3161021966,nop,wscale 7], length 0
13:18:21.273782 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161027086 ecr 0,nop,wscale 7], length 0
13:18:21.273798 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161027086 ecr 3161021966,nop,wscale 7], length 0
13:18:23.289806 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161029102 ecr 3161021966,nop,wscale 7], length 0
13:18:23.289819 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161029102 ecr 0,nop,wscale 7], length 0
13:18:23.289841 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161029102 ecr 3161021966,nop,wscale 7], length 0
13:18:27.385713 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161033198 ecr 0,nop,wscale 7], length 0
13:18:27.385723 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161033198 ecr 3161021966,nop,wscale 7], length 0
13:18:27.385725 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161033198 ecr 3161021966,nop,wscale 7], length 0
13:18:35.578007 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161041390 ecr 3161021966,nop,wscale 7], length 0
13:18:35.578059 IP localhost.49930 > localhost.50052: Flags [S], seq 1186867103, win 65495, options [mss 65495,sackOK,TS val 3161041390 ecr 0,nop,wscale 7], length 0
13:18:35.578074 IP localhost.49930 > localhost.50052: Flags [.], ack 1, win 512, options [nop,nop,TS val 3161041390 ecr 3161041390], length 0
13:18:35.578118 IP localhost.50052 > localhost.49930: Flags [S.], seq 1608855237, ack 1186867104, win 65483, options [mss 65495,sackOK,TS val 3161041390 ecr 3161021966,nop,wscale 7], length 0
13:18:35.578132 IP localhost.49930 > localhost.50052: Flags [.], ack 1, win 512, options [nop,nop,TS val 3161041390 ecr 3161041390], length 0
13:18:35.578692 IP localhost.49930 > localhost.50052: Flags [P.], seq 1:25, ack 1, win 512, options [nop,nop,TS val 3161041391 ecr 3161041390], length 24
13:18:35.578730 IP localhost.50052 > localhost.49930: Flags [.], ack 25, win 512, options [nop,nop,TS val 3161041391 ecr 3161041391], length 0
13:18:35.578867 IP localhost.49930 > localhost.50052: Flags [P.], seq 25:34, ack 1, win 512, options [nop,nop,TS val 3161041391 ecr 3161041391], length 9
...

[mju]

@arjan-bal I was thinking whether there would be some room for golang gRPC to improve the overall experience on this. I feel there is a possibility that this can be improved transparently to the users. From a programmer's perspective, when we do a simple unary gRPC call, we want it to succeed as soon as possible. I am guessing the gRPC considers TCP config a layer 4 and OS thing that users should configure separately. But if under the hood, when gRPC suspects that a transport for a channel is dead already (half closed without an RST sent to client), it can just aggressively close it. Anything less than 16 minutes would be better. Is there any downside to gRPC setting a TCP USER TIMEOUT that is < 3m?

[arjan-bal]

Thanks for sharing the detailed repro. IIUC, the request is to know if gRPC can set a better default for TCP_USER_TIMEOUT creating transports.

This would mean gRPC doesn't respect the OS default, which may be a concern. This also looks like something all gRPC implementations should agree on. Let me check with other maintainers and come back.

[arjan-bal]

You can always set TCP_USER_TIMEOUT using a custom dialer by using the WithContextDialer dial option.

func netDialerWithTCPKeepalive() *net.Dialer {
    timeoutMillis := 180000
    return &net.Dialer{
        KeepAlive: time.Duration(-1),
        Control: func(_, _ string, c syscall.RawConn) error {
            return c.Control(func(fd uintptr) {
                unix.SetsockoptInt(int(fd), unix.SOL_SOCKET, unix.SO_KEEPALIVE, 1)
                syscall.SetsockoptInt(int(fd), syscall.IPPROTO_TCP, unix.TCP_USER_TIMEOUT, timeoutMillis)
            })
        },
    }
}

func tcpDialer(ctx context.Context, address string) (net.Conn, error) {
    return netDialerWithTCPKeepalive().DialContext(ctx, "tcp", address)
}

opts = append(opts, grpc.WithContextDialer(tcpDialer))

[arjan-bal]

Found out that the gRFC mentions setting TCP_USER_TIMEOUT:

Reusing the KEEPALIVE_TIMEOUT configuration has a few repercussions.

• // Omitted
• A KEEPALIVE_TIME configuration of infinite disables keepalive and TCP_USER_TIMEOUT will also not be set. The system default will continue to be in effect.
• TCP_USER_TIMEOUT will have the same default value of 20 seconds as the keepalive timeout, if keepalive is enabled (KEEPALIVE_TIME is not infinite).

gRPC Go is also following this: https://github.com/grpc/grpc-go/blob/e4b09f111dd3856bc1a3ed4b234edbb5d3a861c1/internal/transport/http2_client.go#L268-L273

[arjan-bal]

Since the gRFC is clear about setting TCP_USER_TIMEOUT only when keepalive is enabled, and using system defaults otherwise, a decision to change this behaviour would require an update to the gRFC.

@mju, you will need to follow the process mentioned here to propose a change to the gRFC: https://github.com/grpc/proposal?tab=readme-ov-file#process

[mju]

Yes. We eventually enabled keepalive and set a timeout for TCP_USER_TIMEOUT. We have been testing it in production.

For now, I think we can close this ticket. It might be trickier than I thought to override the system default. Here, we want it because we assume the situation where connections can be half-closed. What if the server is just slow?

There are probably a lot of fun things gRPC can try to do in terms of underlying connection/channel management. I think users mostly want smoother experiences instead of wanting gRPC to not configure anything on transport layer on users' behalf. I might be wrong. I was thinking if gRPC's client library notices that most requests that run out of tcp_retries2 would succeed upon killing the existing connection and creating a new one, it should be confident that there is probably some network issue that drops TCP connections from time to time. In this case, it's okay to set TCP_USER_TIMEOUT to 1-2m dynamically for now. If it takes less time then all the retries caused by tcp_retries2 would, then the server is probably just slow and closing connections early won't help as the new connections will still have to wait. For debuggability, it should be possible to print such automatically configuration changes under the hood. That said, this model sounds more dynamic and complicated. When things go wrong, it'd be harder to debug.

Thanks for the help.