grpc-js server: send GOAWAY debug data for idle timeout (max_idle) and graceful shutdown

Is your feature request related to a problem? Please describe.

Location (grpc/grpc-node @ default branch ca7f83f):

packages/grpc-js/src/server.ts:1038-1056 — closeSession
packages/grpc-js/src/server.ts:1941 — idle timeout path
packages/grpc-js/src/server.ts:1247 — tryShutdown() path
packages/grpc-js/src/server.ts:1542-1546 — max-age path, with kMaxAge

    if (session.closed) {
      queueMicrotask(closeCallback);
    } else {
      session.close(closeCallback);
    }

Problem

When grpc.max_connection_idle_ms closes a connection, or when server.tryShutdown() drains connections, the GOAWAY frames from a grpc-js server have empty debug data. For connections closed by grpc.max_connection_age_ms, grpc-js already sends max_age. When a client log or packet capture shows a GOAWAY, the debug data is the only way to tell which of these lifecycle events closed the connection. An empty value doesn't say whether it was an idle close or a planned shutdown. This is a diagnostic improvement; I am not claiming any effect on RPCs.

gRFC A9 specifies the idle case:

To close the server should send GOAWAY with status code NO_ERROR and ASCII debug data max_idle and then continue the graceful connection termination.

The idle timeout path and tryShutdown() both go through closeSession, which calls only session.close(), so no opaque data is set.

Reproduction

A client using Node's http2 module, connected to a Server with grpc.max_connection_idle_ms: 500 or shut down with tryShutdown(), receives GOAWAY frames whose opaqueData is "":

Uncaught AssertionError [ERR_ASSERTION]: Expected at least one GOAWAY frame with "max_idle" debug_data, but received GOAWAY frames with debug_data: ["",""]
Uncaught AssertionError [ERR_ASSERTION]: Expected at least one GOAWAY frame with "graceful_stop" debug_data, but received GOAWAY frames with debug_data: ["",""]

Test used (public API only; place in packages/grpc-js/test/ and run npm test)

import * as assert from 'assert';
import * as http2 from 'http2';
import { Server, ServerCredentials } from '../src';

describe('GOAWAY debug_data', () => {
  describe('max_connection_idle', () => {
    let server: Server;
    let port: number;

    beforeEach(done => {
      server = new Server({
        'grpc.max_connection_idle_ms': 500,
      });
      server.bindAsync(
        'localhost:0',
        ServerCredentials.createInsecure(),
        (err, boundPort) => {
          assert.ifError(err);
          port = boundPort;
          done();
        }
      );
    });

    afterEach(done => {
      server.tryShutdown(done);
    });

    it('should send max_idle as debug_data in GOAWAY when idle timeout expires', function (done) {
      this.timeout(5000);

      const client = http2.connect(`http://localhost:${port}`);
      const receivedGoAwayData: string[] = [];

      client.on('goaway', (errorCode: number, lastStreamID: number, opaqueData: Buffer) => {
        const debugData = opaqueData ? opaqueData.toString() : '';
        receivedGoAwayData.push(debugData);
      });

      client.on('close', () => {
        const hasMaxIdle = receivedGoAwayData.some(d => d.includes('max_idle'));
        assert.ok(
          hasMaxIdle,
          'Expected at least one GOAWAY frame with "max_idle" debug_data, ' +
          'but received GOAWAY frames with debug_data: ' +
          JSON.stringify(receivedGoAwayData)
        );
        done();
      });
    });
  });

  describe('graceful_stop', () => {
    let server: Server;
    let port: number;

    beforeEach(done => {
      server = new Server();
      server.bindAsync(
        'localhost:0',
        ServerCredentials.createInsecure(),
        (err, boundPort) => {
          assert.ifError(err);
          port = boundPort;
          done();
        }
      );
    });

    it('should send graceful_stop as debug_data in GOAWAY when server shuts down gracefully', function (done) {
      this.timeout(5000);

      const client = http2.connect(`http://localhost:${port}`);
      const receivedGoAwayData: string[] = [];

      client.on('goaway', (errorCode: number, lastStreamID: number, opaqueData: Buffer) => {
        const debugData = opaqueData ? opaqueData.toString() : '';
        receivedGoAwayData.push(debugData);
      });

      client.on('close', () => {
        const hasGracefulStop = receivedGoAwayData.some(d => d.includes('graceful_stop'));
        assert.ok(
          hasGracefulStop,
          'Expected at least one GOAWAY frame with "graceful_stop" debug_data, ' +
          'but received GOAWAY frames with debug_data: ' +
          JSON.stringify(receivedGoAwayData)
        );
        done();
      });

      // Wait for the connection to be established, then trigger a graceful shutdown
      client.once('connect', () => {
        server.tryShutdown(err => {
          assert.ifError(err);
        });
      });
    });
  });
});

Environment:

Commit: 6741e13; server.ts has the same blob on current master ca7f83f, where I did not re-run the test
Toolchain: Node v20.19.6, @grpc/grpc-js 1.13.4

Describe the solution you'd like

Already implemented in grpc/grpc-go

PR: grpc/grpc-go#6220 — "server/transport: send appropriate debug_data in GOAWAY frames" (merged 2023-05-03T16:58:07Z, merge commit 56b33d5cd0b). It made the grpc-go server send max_idle, max_age and graceful_stop as GOAWAY debug data through a debugData argument on Drain.

How grpc-go fixed it:

--- a/internal/transport/http2_server.go
+++ b/internal/transport/http2_server.go
@@ -1166,12 +1166,12 @@ func (t *http2Server) keepalive() {
 			if val <= 0 {
 				// The connection has been idle for a duration of keepalive.MaxConnectionIdle or more.
 				// Gracefully close the connection.
-				t.Drain()
+				t.Drain("max_idle")
 				return
 			}
 			idleTimer.Reset(val)
 		case <-ageTimer.C:
-			t.Drain()
+			t.Drain("max_age")
 			ageTimer.Reset(t.kp.MaxConnectionAgeGrace)
 			select {
 			case <-ageTimer.C:
...
@@ -1318,14 +1318,14 @@ func (t *http2Server) RemoteAddr() net.Addr {
 	return t.remoteAddr
 }
 
-func (t *http2Server) Drain() {
+func (t *http2Server) Drain(debugData string) {
 	t.mu.Lock()
 	defer t.mu.Unlock()
 	if t.drainEvent != nil {
 		return
 	}
 	t.drainEvent = grpcsync.NewEvent()
-	t.controlBuf.put(&goAway{code: http2.ErrCodeNo, debugData: []byte{}, headsUp: true})
+	t.controlBuf.put(&goAway{code: http2.ErrCodeNo, debugData: []byte(debugData), headsUp: true})
 }
 
 var goAwayPing = &ping{data: [8]byte{1, 6, 1, 8, 0, 3, 3, 9}}
...
@@ -1367,7 +1367,7 @@ func (t *http2Server) outgoingGoAwayHandler(g *goAway) (bool, error) {
 	// originated before the GoAway reaches the client.
 	// After getting the ack or timer expiration send out another GoAway this
 	// time with an ID of the max stream server intends to process.
-	if err := t.framer.fr.WriteGoAway(math.MaxUint32, http2.ErrCodeNo, []byte{}); err != nil {
+	if err := t.framer.fr.WriteGoAway(math.MaxUint32, http2.ErrCodeNo, g.debugData); err != nil {
 		return false, err
 	}
 	if err := t.framer.fr.WritePing(false, goAwayPing.data); err != nil {

--- a/server.go
+++ b/server.go
@@ -1856,7 +1856,7 @@ func (s *Server) GracefulStop() {
 	if !s.drain {
 		for _, conns := range s.conns {
 			for st := range conns {
-				st.Drain()
+				st.Drain("graceful_stop")
 			}
 		}
 		s.drain = true

Suggested fix

Send max_idle on the idle timeout, as A9 specifies, and graceful_stop on tryShutdown(), grpc-go's string for this case. closeSession sends a GOAWAY with the debug data the same way the existing max_age path does, and then closes as before; drain(), forceShutdown() and the max_age path are unchanged:

diff --git a/packages/grpc-js/src/server.ts b/packages/grpc-js/src/server.ts
--- a/packages/grpc-js/src/server.ts
+++ b/packages/grpc-js/src/server.ts
@@ -99,6 +99,8 @@ const { HTTP2_HEADER_PATH } = http2.constants;
 
 const TRACER_NAME = 'server';
 const kMaxAge = Buffer.from('max_age');
+const kMaxIdle = Buffer.from('max_idle');
+const kGracefulStop = Buffer.from('graceful_stop');
 
 function serverCallTrace(text: string) {
   logging.trace(LogVerbosity.DEBUG, 'server_call', text);
@@ -1037,7 +1039,8 @@ export class Server {
 
   private closeSession(
     session: http2.ServerHttp2Session,
-    callback?: () => void
+    callback?: () => void,
+    goawayDebugData?: Buffer
   ) {
     this.trace('Closing session initiated by ' + session.socket?.remoteAddress);
     const sessionInfo = this.sessions.get(session);
@@ -1051,6 +1054,20 @@ export class Server {
     if (session.closed) {
       queueMicrotask(closeCallback);
     } else {
+      if (goawayDebugData) {
+        try {
+          session.goaway(
+            http2.constants.NGHTTP2_NO_ERROR,
+            ~(1 << 31),
+            goawayDebugData
+          );
+        } catch (e) {
+          // The goaway can't be sent because the session is already closed
+          session.destroy();
+          queueMicrotask(closeCallback);
+          return;
+        }
+      }
       session.close(closeCallback);
     }
   }
@@ -1244,10 +1261,14 @@ export class Server {
         pendingChecks++;
         const sessionString = session.socket?.remoteAddress;
         this.trace('Waiting for session ' + sessionString + ' to close');
-        this.closeSession(session, () => {
-          this.trace('Session ' + sessionString + ' finished closing');
-          maybeCallback();
-        });
+        this.closeSession(
+          session,
+          () => {
+            this.trace('Session ' + sessionString + ' finished closing');
+            maybeCallback();
+          },
+          kGracefulStop
+        );
       }
     }
 
@@ -1938,7 +1959,7 @@ export class Server {
             sessionInfo.lastIdle
         );
 
-        ctx.closeSession(session);
+        ctx.closeSession(session, undefined, kMaxIdle);
       } else {
         sessionInfo.timeout.refresh();
       }

Verified on 6741e13 (Node.js v22.23.4, mocha 10.8.2): the test above fails without this patch and passes with it; no other test results change.

I can submit a PR for this.

Describe alternatives you've considered

Turning on server tracing (GRPC_TRACE=server) logs "Session idle timeout triggered" on the server side, but clients and intermediaries cannot see that information.

Additional context

Related: I searched existing issues and PRs (GOAWAY debug data, goaway max_idle OR graceful_stop, max_connection_idle goaway) and found no request for this. #3068 and #3089 cover keepalive PINGs after a graceful GOAWAY, which is a separate problem.

Navigation Menu

Repository navigation

grpc-js server: send GOAWAY debug data for idle timeout (`max_idle`) and graceful shutdown #3122

Is your feature request related to a problem? Please describe.

Describe the solution you'd like

Describe alternatives you've considered

Additional context

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

grpc-js server: send GOAWAY debug data for idle timeout (max_idle) and graceful shutdown #3122

Description

Is your feature request related to a problem? Please describe.

Describe the solution you'd like

Describe alternatives you've considered

Additional context

Activity

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

grpc-js server: send GOAWAY debug data for idle timeout (`max_idle`) and graceful shutdown #3122