[server] SpiceDB client: retry with new client on "Waiting for LB pick" error

Tool: gitpod/catfood.gitpod.cloud

Author: geropl

components/gitpod-protocol/src/util/grpc.ts

@@ -110,7 +110,7 @@ export function createClientCallMetricsInterceptor(metrics: IClientCallMetrics):
     };
 }
 
-export function createDebugLogInterceptor(): grpc.Interceptor {
+export function createDebugLogInterceptor(additionalContextF: (() => object) | undefined): grpc.Interceptor {
     const FAILURE_STATUS_CODES = new Map([
         [Status.ABORTED, true],
         [Status.CANCELLED, true],
@@ -139,11 +139,21 @@ export function createDebugLogInterceptor(): grpc.Interceptor {
             .withStart((metadata, listener, next) => {
                 const newListener = new grpc.ListenerBuilder()
                     .withOnReceiveStatus((status, next) => {
+                        // If given, call the additionalContext function and log the result
+                        let additionalContext = {};
+                        try {
+                            if (additionalContextF) {
+                                additionalContext = additionalContextF();
+                            }
+                        } catch (e) {}
+
                         try {
                             const info = {
                                 labels: new TrustedValue(labels),
                                 metadata: new TrustedValue(metadata.toJSON()),
                                 code: Status[status.code],
+                                details: status.details,
+                                additionalContext: new TrustedValue(additionalContext),
                             };
                             if (FAILURE_STATUS_CODES.has(status.code)) {
                                 log.warn(`grpc call failed`, info);

components/server/src/authorization/spicedb-authorizer.ts

@@ -174,16 +174,52 @@ export class SpiceDBAuthorizer {
         return this.call("readRelationships failed.", (client) => client.readRelationships(req, this.callOptions));
     }
 
-    private async call<T>(errMessage: string, code: (client: v1.ZedPromiseClientInterface) => Promise<T>): Promise<T> {
-        try {
-            const client = this.clientProvider.getClient();
-            return code(client);
-        } catch (err) {
-            log.error(errMessage, err, {
-                code: err.code,
-            });
-            throw err;
+    /**
+     * call retrieves a Spicedb client and executes the given code block.
+     * In addition to the gRPC-level retry mechanisms, it retries on "Waiting for LB pick" errors.
+     * This is required, because we seem to be running into a grpc/grpc-js bug where a subchannel takes 120s+ to reconnect.
+     * @param description
+     * @param code
+     * @returns
+     */
+    private async call<T>(description: string, code: (client: v1.ZedPromiseClientInterface) => Promise<T>): Promise<T> {
+        const MAX_ATTEMPTS = 3;
+        let attempt = 0;
+        while (attempt++ < 3) {
+            try {
+                const checkClient = attempt > 1; // the last client error'd out, so check if we should get a new one
+                const client = this.clientProvider.getClient(checkClient);
+                return code(client);
+            } catch (err) {
+                // Check: Is this a "no connection to upstream" error? If yes, retry here, to work around grpc/grpc-js bugs introducing high latency for re-tries
+                if (
+                    (err.code === grpc.status.DEADLINE_EXCEEDED || err.code === grpc.status.UNAVAILABLE) &&
+                    attempt < MAX_ATTEMPTS
+                ) {
+                    let delay = 500 * attempt;
+                    if (err.code === grpc.status.DEADLINE_EXCEEDED) {
+                        // we already waited for timeout, so let's try again immediately
+                        delay = 0;
+                    }
+
+                    log.warn(description, err, {
+                        attempt,
+                        delay,
+                        code: err.code,
+                    });
+                    await new Promise((resolve) => setTimeout(resolve, delay));
+                    continue;
+                }
+
+                // Some other error: log and rethrow
+                log.error(description, err, {
+                    attempt,
+                    code: err.code,
+                });
+                throw err;
+            }
         }
+        throw new Error("unreachable");
     }
 
     /**

components/server/src/authorization/spicedb.ts

@@ -9,6 +9,8 @@ import { log } from "@gitpod/gitpod-protocol/lib/util/logging";
 import * as grpc from "@grpc/grpc-js";
 import { getExperimentsClientForBackend } from "@gitpod/gitpod-protocol/lib/experiments/configcat-server";
 import { TrustedValue } from "@gitpod/gitpod-protocol/lib/util/scrubbing";
+import { createDebugLogInterceptor } from "@gitpod/gitpod-protocol/lib/util/grpc";
+import { isConnectionAlive } from "@gitpod/gitpod-protocol/lib/util/grpc";
 
 export interface SpiceDBClientConfig {
     address: string;
@@ -54,6 +56,7 @@ const DefaultClientOptions: grpc.ClientOptions = {
     // default is 30s, which is too long for us during rollouts (where service DNS entries are updated)
     "grpc.dns_min_time_between_resolutions_ms": 2_000,
 };
+const CLIENT_CLOSE_DELAY = 60_000; // 60 [s]
 
 export function spiceDBConfigFromEnv(): SpiceDBClientConfig | undefined {
     const token = process.env["SPICEDB_PRESHARED_KEY"];
@@ -110,9 +113,7 @@ export class SpiceDBClientProvider {
                 });
 
                 // close client after 2 minutes to make sure most pending requests on the previous client are finished.
-                setTimeout(() => {
-                    this.closeClient(oldClient);
-                }, 2 * 60 * 1000);
+                this.closeClientAfter(oldClient, CLIENT_CLOSE_DELAY);
             }
             this.clientOptions = clientOptions;
             // `createClient` will use the `DefaultClientOptions` to create client if the value on Feature Flag is not able to create a client
@@ -132,48 +133,77 @@ export class SpiceDBClientProvider {
         })();
     }
 
-    private closeClient(client: Client) {
-        try {
-            client.close();
-        } catch (error) {
-            log.error("[spicedb] Error closing client", error);
-        }
+    private closeClientAfter(client: Client, timeout: number): void {
+        setTimeout(() => {
+            try {
+                client.close();
+            } catch (error) {
+                log.error("[spicedb] Error closing client", error);
+            }
+        }, timeout);
     }
 
     private createClient(clientOptions: grpc.ClientOptions): Client {
         log.debug("[spicedb] Creating client", {
             clientOptions: new TrustedValue(clientOptions),
         });
+
+        // Inject debugLogInterceptor to log details especially on failed grpc calls
+        let client: Client;
+        const debugInfo = (): object => {
+            if (!client) {
+                return {};
+            }
+            const ch = client.getChannel();
+            return {
+                target: ch.getTarget(),
+                state: ch.getConnectivityState(false),
+            };
+        };
+        const interceptors = [...(this.interceptors || []), createDebugLogInterceptor(debugInfo)];
+
+        // Create the actual client
         try {
-            return v1.NewClient(
+            client = v1.NewClient(
                 this.clientConfig.token,
                 this.clientConfig.address,
                 v1.ClientSecurity.INSECURE_PLAINTEXT_CREDENTIALS,
                 undefined,
                 {
                     ...clientOptions,
-                    interceptors: this.interceptors,
+                    interceptors,
                 },
             ) as Client;
         } catch (error) {
             log.error("[spicedb] Error create client, fallback to default options", error);
-            return v1.NewClient(
+            client = v1.NewClient(
                 this.clientConfig.token,
                 this.clientConfig.address,
                 v1.ClientSecurity.INSECURE_PLAINTEXT_CREDENTIALS,
                 undefined,
                 {
                     ...DefaultClientOptions,
-                    interceptors: this.interceptors,
+                    interceptors,
                 },
             ) as Client;
         }
+        return client;
     }
 
-    getClient(): SpiceDBClient {
+    getClient(checkClient: boolean = false): SpiceDBClient {
         if (!this.client) {
             this.client = this.createClient(this.clientOptions);
         }
+
+        if (checkClient) {
+            const oldClient = this.client;
+            if (!isConnectionAlive(oldClient)) {
+                const connectivityState = oldClient.getChannel().getConnectivityState(false);
+                log.warn("[spicedb] Client is not alive, creating a new one", { connectivityState });
+                this.closeClientAfter(oldClient, CLIENT_CLOSE_DELAY);
+                this.client = this.createClient(this.clientOptions);
+            }
+        }
         return this.client.promises;
     }
 }

components/server/src/container-module.ts

@@ -15,7 +15,6 @@ import { DebugApp } from "@gitpod/gitpod-protocol/lib/util/debug-app";
 import {
     IClientCallMetrics,
     createClientCallMetricsInterceptor,
-    createDebugLogInterceptor,
     defaultGRPCOptions,
 } from "@gitpod/gitpod-protocol/lib/util/grpc";
 import { prometheusClientMiddleware } from "@gitpod/gitpod-protocol/lib/util/nice-grpc";
@@ -342,7 +341,7 @@ export const productionContainerModule = new ContainerModule(
                 const clientCallMetrics = ctx.container.get<IClientCallMetrics>(IClientCallMetrics);
                 return new SpiceDBClientProvider(
                     config, //
-                    [createClientCallMetricsInterceptor(clientCallMetrics), createDebugLogInterceptor()],
+                    [createClientCallMetricsInterceptor(clientCallMetrics)],
                 );
             })
             .inSingletonScope();