[public-api] add request context

components/dashboard/src/service/metrics.ts

@@ -4,7 +4,6 @@
  * See License.AGPL.txt in the project root for license information.
  */
 
-import { GitpodHostUrl } from "@gitpod/gitpod-protocol/lib/util/gitpod-host-url";
 import { MetricsReporter } from "@gitpod/public-api/lib/metrics";
 import { getExperimentsClient } from "../experiments/client";
 import { v4 } from "uuid";
@@ -13,7 +12,7 @@ const commit = require("./config.json").commit;
 const originalConsoleError = console.error;
 
 const metricsReporter = new MetricsReporter({
-    gitpodUrl: new GitpodHostUrl(window.location.href).withoutWorkspacePrefix().toString(),
+    gitpodUrl: window.location.href,
     clientName: "dashboard",
     clientVersion: commit,
     log: {

components/server/src/api/dummy.ts

@@ -24,7 +24,7 @@ export class APIHelloService implements ServiceImpl<typeof HelloService> {
     }
     async *lotsOfReplies(req: LotsOfRepliesRequest, context: HandlerContext): AsyncGenerator<LotsOfRepliesResponse> {
         let count = req.previousCount || 0;
-        while (true) {
+        while (!context.signal.aborted) {
             const response = new LotsOfRepliesResponse();
             response.reply = `Hello ${this.getSubject(context)} ${count}`;
             response.count = count;

components/server/src/api/server.ts

@@ -24,6 +24,9 @@ import { APIStatsService } from "./stats";
 import { APITeamsService } from "./teams";
 import { APIUserService } from "./user";
 import { APIWorkspacesService } from "./workspaces";
+import { LogContextOptions, wrapAsyncGenerator, runWithContext } from "../util/log-context";
+import { v4 } from "uuid";
+import { performance } from "perf_hooks";
 
 function service<T extends ServiceType>(type: T, impl: ServiceImpl<T>): [T, ServiceImpl<T>] {
     return [type, impl];
@@ -90,9 +93,9 @@ export class API {
      * intercept handles cross-cutting concerns for all calls:
      * - authentication
      * - server-side observability
+     * - logging context
      * TODO(ak):
      * - rate limitting
-     * - logging context
      * - tracing
      */
     private interceptService<T extends ServiceType>(type: T): ProxyHandler<ServiceImpl<T>> {
@@ -101,10 +104,22 @@ export class API {
         return {
             get(target, prop) {
                 return (...args: any[]) => {
-                    const method = type.methods[prop as any];
+                    const logContext: LogContextOptions & {
+                        requestId?: string;
+                        contextTimeMs: number;
+                        grpc_service: string;
+                        grpc_method: string;
+                    } = {
+                        contextTimeMs: performance.now(),
+                        grpc_service,
+                        grpc_method: prop as string,
+                    };
+                    const withRequestContext = <T>(fn: () => T): T => runWithContext("public-api", logContext, fn);
+
+                    const method = type.methods[prop as string];
                     if (!method) {
                         // Increment metrics for unknown method attempts
-                        console.warn("public api: unknown method", grpc_service, prop);
+                        withRequestContext(() => log.warn("public api: unknown method"));
                         const code = Code.Unimplemented;
                         grpcServerStarted.labels(grpc_service, "unknown", "unknown").inc();
                         grpcServerHandled.labels(grpc_service, "unknown", "unknown", Code[code]).inc();
@@ -123,55 +138,78 @@ export class API {
                         grpc_type = "bidi_stream";
                     }
 
+                    logContext.requestId = v4();
+
                     grpcServerStarted.labels(grpc_service, grpc_method, grpc_type).inc();
                     const stopTimer = grpcServerHandling.startTimer({ grpc_service, grpc_method, grpc_type });
                     const done = (err?: ConnectError) => {
                         const grpc_code = err ? Code[err.code] : "OK";
                         grpcServerHandled.labels(grpc_service, grpc_method, grpc_type, grpc_code).inc();
                         stopTimer({ grpc_code });
+                        let callMs: number | undefined;
+                        if (callStartedAt) {
+                            callMs = performance.now() - callStartedAt;
+                        }
+                        log.debug("public api: done", { grpc_code, verifyMs, callMs });
+                        // right now p99 for getLoggetInUser is around 100ms, using it as a threshold for now
+                        const slowThreshold = 100;
+                        const totalMs = performance.now() - logContext.contextTimeMs;
+                        if (grpc_type === "unary" && totalMs > slowThreshold) {
+                            log.warn("public api: slow unary call", { grpc_code, callMs, verifyMs });
+                        }
                     };
                     const handleError = (reason: unknown) => {
                         let err = ConnectError.from(reason, Code.Internal);
                         if (reason != err && err.code === Code.Internal) {
-                            console.error("public api: unexpected internal error", reason);
-                            // don't leak internal errors to a user
-                            // TODO(ak) instead surface request id
-                            err = ConnectError.from(`please check server logs`, Code.Internal);
+                            log.error("public api: unexpected internal error", reason);
+                            err = ConnectError.from(
+                                `Oops! Something went wrong. Please quote the request ID ${logContext.requestId} when reaching out to Gitpod Support.`,
+                                Code.Internal,
+                            );
                         }
                         done(err);
                         throw err;
                     };
 
+                    let verifyMs: number | undefined;
+                    let callStartedAt: number | undefined;
                     const context = args[1] as HandlerContext;
-                    async function call<T>(): Promise<T> {
+
+                    const apply = async <T>(): Promise<T> => {
+                        const verifyStartedAt = performance.now();
                         const user = await self.verify(context);
+                        verifyMs = performance.now() - verifyStartedAt;
                         context.user = user;
 
-                        return (target[prop as any] as Function).apply(target, args);
-                    }
+                        callStartedAt = performance.now();
+                        return Reflect.apply(target[prop as any], target, args);
+                    };
                     if (grpc_type === "unary" || grpc_type === "client_stream") {
-                        return (async () => {
+                        return withRequestContext(async () => {
                             try {
-                                const promise = await call<Promise<any>>();
+                                const promise = await apply<Promise<any>>();
                                 const result = await promise;
                                 done();
                                 return result;
                             } catch (e) {
                                 handleError(e);
                             }
-                        })();
+                        });
                     }
-                    return (async function* () {
-                        try {
-                            const generator = await call<AsyncGenerator<any>>();
-                            for await (const item of generator) {
-                                yield item;
+                    return wrapAsyncGenerator(
+                        (async function* () {
+                            try {
+                                const generator = await apply<AsyncGenerator<any>>();
+                                for await (const item of generator) {
+                                    yield item;
+                                }
+                                done();
+                            } catch (e) {
+                                handleError(e);
                             }
-                            done();
-                        } catch (e) {
-                            handleError(e);
-                        }
-                    })();
+                        })(),
+                        withRequestContext,
+                    );
                 };
             },
         };

components/server/src/server.ts

@@ -144,7 +144,7 @@ export class Server {
         app.use(async (req: express.Request, res: express.Response, next: express.NextFunction) => {
             try {
                 const userId = req.user ? req.user.id : undefined;
-                await runWithContext("http", { userId, requestPath: req.path }, () => next());
+                runWithContext("http", { userId, requestPath: req.path }, () => next());
             } catch (err) {
                 next(err);
             }

components/server/src/util/log-context.ts

@@ -6,20 +6,27 @@
 
 import { LogContext } from "@gitpod/gitpod-protocol/lib/util/logging";
 import { AsyncLocalStorage } from "node:async_hooks";
+import { performance } from "node:perf_hooks";
 import { v4 } from "uuid";
 
+export type LogContextOptions = LogContext & {
+    contextId?: string;
+    contextTimeMs?: number;
+    [p: string]: any;
+};
+
 // we are installing a special augmenter that enhances the log context if executed within `runWithContext`
 // with a contextId and a contextTimeMs, which denotes the amount of milliseconds since the context was created.
-type EnhancedLogContext = LogContext & {
-    contextId?: string;
-    contextTimeMs: number;
+type EnhancedLogContext = LogContextOptions & {
     contextKind: string;
+    contextId: string;
+    contextTimeMs: number;
 };
 
 const asyncLocalStorage = new AsyncLocalStorage<EnhancedLogContext>();
 const augmenter: LogContext.Augmenter = (ctx) => {
     const globalContext = asyncLocalStorage.getStore();
-    const contextTimeMs = globalContext?.contextTimeMs ? Date.now() - globalContext.contextTimeMs : undefined;
+    const contextTimeMs = globalContext?.contextTimeMs ? performance.now() - globalContext.contextTimeMs : undefined;
     const result = {
         ...globalContext,
         contextTimeMs,
@@ -30,18 +37,30 @@ const augmenter: LogContext.Augmenter = (ctx) => {
 };
 LogContext.setAugmenter(augmenter);
 
-export async function runWithContext<T>(
-    contextKind: string,
-    context: LogContext & { contextId?: string } & any,
-    fun: () => T,
-): Promise<T> {
+export function runWithContext<T>(contextKind: string, context: LogContextOptions, fun: () => T): T {
     return asyncLocalStorage.run(
         {
             ...context,
             contextKind,
             contextId: context.contextId || v4(),
-            contextTimeMs: Date.now(),
+            contextTimeMs: context.contextTimeMs || performance.now(),
         },
         fun,
     );
 }
+
+export type AsyncGeneratorDecorator<T> = (f: () => T) => T;
+export function wrapAsyncGenerator<T>(
+    generator: AsyncGenerator<T>,
+    decorator: AsyncGeneratorDecorator<any>,
+): AsyncGenerator<T> {
+    return <AsyncGenerator<T>>{
+        next: () => decorator(() => generator.next()),
+        return: (value?: any) => decorator(() => generator.return(value)),
+        throw: (e?: any) => decorator(() => generator.throw(e)),
+
+        [Symbol.asyncIterator]() {
+            return this;
+        },
+    };
+}