Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Unexpected HTTP2 END_STREAM and keep alive behavior #113

Closed
RichardLaos opened this issue Feb 16, 2022 · 9 comments
Closed

Unexpected HTTP2 END_STREAM and keep alive behavior #113

RichardLaos opened this issue Feb 16, 2022 · 9 comments
Assignees
@ahmelsayed
Labels
wontfix This will not be worked on

Comments

@RichardLaos
Copy link

When running a gRPC application that is configured to send http2 keep alive pings the container app will timeout a stream after 4 minutes. This can be seen in the following http2 trace:

2022/02/15 16:31:37 http2: Framer 0xc00026c540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/02/15 16:31:37 http2: Framer 0xc00026c540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/02/15 16:31:47 http2: Framer 0xc00026c540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/02/15 16:31:47 http2: Framer 0xc00026c540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/02/15 16:31:55 http2: Framer 0xc00026c540: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=72
2022/02/15 16:31:55 http2: decoded hpack field header field ":status" = "200"
2022/02/15 16:31:55 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/02/15 16:31:55 http2: decoded hpack field header field "grpc-status" = "2"
2022/02/15 16:31:55 http2: decoded hpack field header field "grpc-message" = "stream timeout"
2022/02/15 16:31:55 http2: decoded hpack field header field "date" = "Wed, 16 Feb 2022 00:31:55 GMT"

This reset is not being sent by the gRPC service itself. Also, it appears the the ingress does not forward the http2 pings between the container instance and the client (it does seem to respond to a ping). When connected directly to the service the trace looks like this:

2022/02/15 16:21:00 http2: Framer 0xc00031a1c0: read WINDOW_UPDATE len=4 (conn) incr=43
2022/02/15 16:21:00 http2: Framer 0xc00031a1c0: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/02/15 16:21:00 http2: Framer 0xc00031a1c0: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/02/15 16:21:10 http2: Framer 0xc00031a1c0: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/02/15 16:21:10 http2: Framer 0xc00031a1c0: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/02/15 16:21:10 http2: Framer 0xc00031a1c0: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/02/15 16:21:10 http2: Framer 0xc00031a1c0: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"

Note that it is reading both PINGs and PING ACKs. Also, when connected directly to the service the stream does not reset.

This seems to be dictated by the ingress configuration. Will there be some way to configure this in the future?
@kendallroden kendallroden added the question Further information is requested label Feb 17, 2022
@RichardLaos
Copy link
Author

RichardLaos commented Mar 2, 2022 •
edited
Loading

I tried this same application with a custom virtual network. Adjusting the idle timeout on both the load balancer and external ip of the subnet had no effect on the timeout time (still 4 minutes). It seems the component that is timing out the connection is part of the kubernetes backend pool. I also verified that the gRPC server application also gets ping acks, but they are not coming from the gRPC client. Something is responding to http2 pings but not allowing them to pass through.

@ahmelsayed
Copy link
Member

Hi @RichardLaos, sorry for the delay. I wanted to try to repro this to see if it's the default timeout we set on idle connection or if something else is causing it.

However, I'm not able to reproduce the issue.

Server 
package main

import (
	"context"
	"log"
	"net"

	"google.golang.org/grpc"
	pb "google.golang.org/grpc/examples/helloworld/helloworld"
)

type server struct {
	pb.UnimplementedGreeterServer
}

func (s *server) SayHello(ctx context.Context, in *pb.HelloRequest) (*pb.HelloReply, error) {
	log.Printf("Received: %v", in.GetName())
	return &pb.HelloReply{Message: "Hello " + in.GetName()}, nil
}
func main() {
	lis, err := net.Listen("tcp", ":50051")
	if err != nil {
		log.Fatalf("failed to listen: %v", err)
	}

	s := grpc.NewServer()
	pb.RegisterGreeterServer(s, &server{})
	log.Printf("server listening at %v", lis.Addr())
	if err := s.Serve(lis); err != nil {
		log.Fatalf("failed to serve: %v", err)
	}
}
Client 
import (
	"context"
	"fmt"
	"os"
	"os/signal"
	"runtime"
	"time"

	"google.golang.org/grpc"
	"google.golang.org/grpc/credentials/insecure"
	pb "google.golang.org/grpc/examples/helloworld/helloworld"
	"google.golang.org/grpc/keepalive"
)

func main() {
	keepaliveParams := keepalive.ClientParameters{
		Time:                  5 * time.Second,
		Timeout:               5 * time.Second,
		PermitWithoutStream: true,
	}


	conn, err := grpc.Dial("greet-server.orangebeach-3169496f.eastus2.azurecontainerapps.io:80",
		grpc.WithTransportCredentials(insecure.NewCredentials()),
		grpc.WithKeepaliveParams(keepaliveParams))
	if err != nil {
		panic(err)
	}

	defer conn.Close()
	c := pb.NewGreeterClient(conn)
	r, err := c.SayHello(context.TODO(), &pb.HelloRequest{Name: "Test"})
	if err != nil {
		panic(err)
	}

	fmt.Println(r.Message)

	fmt.Printf("%+v", conn.GetState())

	cc := make(chan os.Signal, 1)
	signal.Notify(cc, os.Interrupt)
	<-cc
}

and I see pings going on for more than 4 minutes

Client logs 
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: wrote SETTINGS len=0
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read SETTINGS len=0
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: wrote SETTINGS flags=ACK len=0
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: wrote HEADERS flags=END_HEADERS stream=1 len=112
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: wrote DATA flags=END_STREAM stream=1 len=11 data="\x00\x00\x00\x00\x06\n\x04Test"
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read SETTINGS len=30, settings: HEADER_TABLE_SIZE=4096, MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=65536, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=65535
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read WINDOW_UPDATE len=4 (conn) incr=2147418112
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read SETTINGS flags=ACK len=0
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: wrote SETTINGS flags=ACK len=0
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read HEADERS flags=END_HEADERS stream=1 len=71
2022/03/03 17:36:28 http2: decoded hpack field header field ":status" = "200"
2022/03/03 17:36:28 http2: decoded hpack field header field "content-type" = "application/grpc" (sensitive)
2022/03/03 17:36:28 http2: decoded hpack field header field "date" = "Fri, 04 Mar 2022 01:36:29 GMT" (sensitive)
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read DATA stream=1 len=17 data="\x00\x00\x00\x00\f\n\nHello Test"
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=30
2022/03/03 17:36:28 http2: decoded hpack field header field "grpc-status" = "0" (sensitive)
2022/03/03 17:36:28 http2: decoded hpack field header field "grpc-message" = "" (sensitive)
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: wrote WINDOW_UPDATE len=4 (conn) incr=17
Hello Test
READY
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/03/03 17:36:28 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/03/03 17:36:38 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:36:38 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:36:48 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:36:48 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:36:58 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:36:58 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:08 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:08 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:18 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:19 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:29 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:29 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:39 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:39 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:49 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:49 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:59 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:37:59 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:09 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:09 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:19 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:19 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:29 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:29 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:39 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:39 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:49 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:49 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:59 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:38:59 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:09 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:09 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:19 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:20 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:30 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:30 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:40 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:40 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:50 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:39:50 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:00 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:00 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:10 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:10 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:20 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:20 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:30 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:30 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:40 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:40 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:50 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:40:50 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:00 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:00 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:10 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:11 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:21 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:21 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:31 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:31 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:41 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:41 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:51 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:41:51 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:01 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:01 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:11 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:11 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:21 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:21 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:31 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:31 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:41 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:41 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:51 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:42:51 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:01 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:01 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:11 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:12 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:22 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:22 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:32 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:32 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:42 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:42 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:52 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:43:52 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:02 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:02 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:12 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:12 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:22 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:22 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:32 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:32 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:42 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:42 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:52 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:44:52 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:02 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:03 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:13 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:13 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:23 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:23 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:33 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:33 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:43 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:43 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:53 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:45:53 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:03 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:03 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:13 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:13 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:23 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:23 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:33 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:33 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:43 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:43 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:53 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:46:53 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:03 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:04 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:14 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:14 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:24 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:24 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:34 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:34 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:44 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:44 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:54 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:47:54 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:04 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:04 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:14 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:14 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:24 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:24 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:34 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:34 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:44 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:44 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:54 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:48:55 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:49:05 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:49:05 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:49:15 http2: Framer 0xc0000d0000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/03 17:49:15 http2: Framer 0xc0000d0000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"

Can you share a repro I can try?

Regarding pings and the ingress proxy, you are right; pings are not proxies through the proxy. According to this PING frames are only hop-by-hop in HTTP/2 and per-connection, so they won't be proxied.

We can add a setting to have the ingress/proxy ping the upstream (app), but the pings will always be either client <-> ingress, or app <-> ingress.

For client <-> app pings, that will need apps with tcp transport, which aren't available now.

@RichardLaos
Copy link
Author

Hi @ahmelsayed, Thanks for looking into this and the info on the pings. That matches what I am seeing. I think what I am seeing is a stream reset rather than an idle connection being closed. The application I am testing with uses a server side streaming call that leaves the stream open. That stream is what is reset after 4 minutes. I will try to reproduce it with a simple example and share it here. Thanks again.

@RichardLaos
Copy link
Author

I was able to reproduce with a gRPC server stream. In this example the client subscribes and waits to receive messages. The server holds the stream open and sends a message on an interval of 10 minutes. I am seeing the client receive a RST_STREAM after 4 minutes. Receiving a notification during this time does seem to extend the timeout. Apologies for the lack of a proper repro earlier.

Server 
package main

import (
	"fmt"
	"log"
	"net"
	"sync"
	"time"

	pb "github.com/RichardLaos/grpc-stream/notify"
	"google.golang.org/grpc"
	"google.golang.org/grpc/keepalive"
)

type server struct {
	pb.UnimplementedNotifyServer
	subscribers sync.Map
}

type subscriber struct {
	stream pb.Notify_SubscribeServer
	done   chan<- bool
}

func (s *server) Subscribe(request *pb.Request, stream pb.Notify_SubscribeServer) error {
	log.Printf("client subscribed: %s", request.DeviceId)

	done := make(chan bool)
	s.subscribers.Store(request.DeviceId, subscriber{stream: stream, done: done})

	ctx := stream.Context()
	for {
		select {
		case <-done:
			return nil
		case <-ctx.Done():
			// client disconnected
			return nil
		}
	}
}

func main() {
	lis, err := net.Listen("tcp", ":50051")
	if err != nil {
		log.Fatalf("failed to listen: %v", err)
	}

	s := grpc.NewServer(
		grpc.KeepaliveEnforcementPolicy(keepalive.EnforcementPolicy{
			MinTime:             10 * time.Second,
			PermitWithoutStream: true,
		}),
		grpc.KeepaliveParams(keepalive.ServerParameters{
			Time:    10 * time.Second,
			Timeout: 15 * time.Second,
		}),
	)

	ns := &server{}
	go ns.sendNotifications()

	pb.RegisterNotifyServer(s, ns)
	log.Printf("server listening at %v", lis.Addr())
	if err := s.Serve(lis); err != nil {
		log.Fatalf("failed to serve: %v", err)
	}
}

func (s *server) sendNotifications() {
	for {
		time.Sleep(10 * time.Minute)

		var unsubscribe []string

		s.subscribers.Range(func(k, v interface{}) bool {
			id, ok := k.(string)
			if !ok {
				return false
			}

			sub, ok := v.(subscriber)
			if !ok {
				return false
			}
			// Send data over the gRPC stream to the client
			if err := sub.stream.Send(&pb.Notification{Message: fmt.Sprintf("Notification for: %s", id)}); err != nil {
				select {
				case sub.done <- true:
				default:
					// avoid blocking
				}
				unsubscribe = append(unsubscribe, id)
			}
			return true
		})

		// Unsubscribe
		for _, id := range unsubscribe {
			s.subscribers.Delete(id)
		}
	}
}
Client 
package main

import (
	"context"
	"crypto/tls"
	"log"
	"time"

	pb "github.com/RichardLaos/grpc-stream/notify"
	"google.golang.org/grpc"
	"google.golang.org/grpc/credentials"
	"google.golang.org/grpc/keepalive"
)

func main() {
	keepaliveParams := keepalive.ClientParameters{
		Time:                5 * time.Second,
		Timeout:             5 * time.Second,
		PermitWithoutStream: true,
	}

	conn, err := grpc.Dial("stream-server.proudflower-378ee8a3.canadacentral.azurecontainerapps.io:443",
		grpc.WithTransportCredentials(credentials.NewTLS(&tls.Config{})),
		grpc.WithKeepaliveParams(keepaliveParams))
	if err != nil {
		panic(err)
	}

	defer conn.Close()

	c := client{
		client: pb.NewNotifyClient(conn),
		id:     "notify-client-1",
	}

	c.listen()
}

type client struct {
	client pb.NotifyClient
	id     string
}

func (c *client) listen() {
	var err error
	var stream pb.Notify_SubscribeClient

	for {
		if stream == nil {
			if stream, err = c.client.Subscribe(context.Background(), &pb.Request{DeviceId: c.id}); err != nil {
				log.Printf("failed to subscribe: %v", err)
				<-time.After(5 * time.Second)
				// Retry on failure
				continue
			}
		}
		response, err := stream.Recv()
		if err != nil {
			log.Printf("failed to receive: %v", err)
			// Clearing the stream will force the client to resubscribe on next iteration
			stream = nil
			<-time.After(5 * time.Second)
			// Retry on failure
			continue
		}
		log.Printf("device %s got response: %q", c.id, response.Message)
	}
}
Client Logs 
2022/03/04 11:31:13 http2: Framer 0xc00021e540: wrote SETTINGS len=0
2022/03/04 11:31:13 http2: Framer 0xc00021e540: read SETTINGS len=24, settings: HEADER_TABLE_SIZE=4096, UNKNOWN_SETTING_8=0, MAX_CONCURREN
T_STREAMS=100, INITIAL_WINDOW_SIZE=65536
2022/03/04 11:31:13 http2: Framer 0xc00021e540: read WINDOW_UPDATE len=4 (conn) incr=983041
2022/03/04 11:31:13 http2: Framer 0xc00021e540: wrote SETTINGS flags=ACK len=0
2022/03/04 11:31:13 http2: Framer 0xc00021e540: read SETTINGS flags=ACK len=0
2022/03/04 11:31:13 http2: Framer 0xc00021e540: wrote HEADERS flags=END_HEADERS stream=1 len=115
2022/03/04 11:31:13 http2: Framer 0xc00021e540: wrote DATA flags=END_STREAM stream=1 len=22 data="\x00\x00\x00\x00\x11\n\x0fnotify-client-
1"
2022/03/04 11:31:23 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:31:23 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:31:33 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:31:33 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:31:43 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:31:43 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:31:53 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:31:53 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:03 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:03 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:13 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:13 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:23 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:23 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:34 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:34 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:44 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:44 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:54 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:32:54 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:04 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:04 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:14 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:14 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:24 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:24 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:34 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:34 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:44 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:44 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:54 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:33:54 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:04 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:04 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:14 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:15 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:25 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:25 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:35 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:35 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:45 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:45 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:55 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:34:55 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:35:05 http2: Framer 0xc00021e540: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:35:05 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 11:35:13 http2: Framer 0xc00021e540: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=72
2022/03/04 11:35:13 http2: decoded hpack field header field ":status" = "200"
2022/03/04 11:35:13 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/03/04 11:35:13 http2: decoded hpack field header field "grpc-status" = "2"
2022/03/04 11:35:13 http2: decoded hpack field header field "grpc-message" = "stream timeout"
2022/03/04 11:35:13 http2: decoded hpack field header field "date" = "Fri, 04 Mar 2022 19:35:13 GMT"
2022/03/04 11:35:13 failed to receive: rpc error: code = Unknown desc = stream timeout

@RichardLaos
Copy link
Author

Sometimes the error is due to the stream timeout as in the above log. Others it is a RST_STREAM like below:

2022/03/04 16:06:35 http2: Framer 0xc00021e540: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2022/03/04 16:06:37 http2: Framer 0xc00021e540: read RST_STREAM stream=121 len=4 ErrCode=NO_ERROR
2022/03/04 16:06:37 failed to receive: rpc error: code = Internal desc = stream terminated by RST_STREAM with error code: NO_ERROR

@RichardLaos
Copy link
Author

@ahmelsayed Were you able to repro with the new example?

@ahmelsayed
Copy link
Member

ahmelsayed commented Mar 18, 2022 •
edited
Loading

@RichardLaos, Sorry for not getting back to you, and thank you very much for the repro details.
Yes, I have been able to repro it; however, unfortunately there is no easy way to fix it, nor there is necessarily something to be fixed per se. This appears to be a side effect of how HTTP2 PING frames work, and their usage in GRPC KeepAlive, and proxies.

HTTP2 PING are used to verify peer-to-peer connections, and not proxied[1][2].

GRPC KeepAlive uses HTTP2 PING to ensure the connection is alive.

That doesn't ensure that the streams carried over the connection will remain alive because the connection is between peers, while the stream is end-to-end.

For example, envoy (and other proxies) have timeouts on connections and streams. i.e:

client <----conn1----> proxy <----conn2----> app
client <---------------stream1-------------> app

with stream1 being carried over conn1 and conn2. So while conn1 doesn't timeout because of PING, the stream does because nothing is going over the full stream. And GRPC KeepAlive doesn't ensure the stream will be alive.

Today we have a nonconfigurable 4 minutes idleTimeout for conn1, conn2, or stream1. Having reasonable default connection and stream timeout is important for edge proxies, but if you have a particular long lived streaming scenario for a particular application, then you should increase the idleTimeout for it.

  • Fix: The "fix" I can think of would be to expose a configurable streamIdleTimeout for applications, but it'll be up to you to decide what an appropriate timeout vs DoS the user is comfortable with.

  • workaround: have an actual PING message go over the stream end-to-end on a timer and not rely on GRPC KeepAlive.

@RichardLaos
Copy link
Author

@ahmelsayed Thanks for looking into this. The behavior behind a proxy does make sense and the connection itself does stay alive. I am not sure if an application level ping would be more efficient that the rebuilding of the stream when it times out. Both require management of the stream on the server side. A configurable streamIdleTimeout would be a great option to cut down on that overhead.

@kendallroden kendallroden added wontfix This will not be worked on and removed question Further information is requested labels Jun 1, 2022
@torosent torosent mentioned this issue Aug 25, 2022
Closed
@SophCarp
Copy link

SophCarp commented Mar 1, 2023

Looks like this was tagged "won't fix". I am closing the issue. If you feel like it hasn't been resolved, feel free to reopen. Thanks!

@SophCarp SophCarp closed this as completed Mar 1, 2023
@DosangGu DosangGu mentioned this issue Feb 19, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ahmelsayed ahmelsayed

Labels
wontfix This will not be worked on
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@ahmelsayed @RichardLaos @kendallroden @SophCarp