[log] log contextId and userId (#18688)

Author: svenefftinge

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

@@ -20,7 +20,17 @@ export interface LogContext {
     workspaceId?: string;
     instanceId?: string;
 }
+
+/**
+ * allows to globally augment the log context, default is an identity function
+ */
+let logContextAugmenter: LogContext.Augmenter = (context) => context;
+
 export namespace LogContext {
+    export type Augmenter = (context: LogContext | undefined) => LogContext | undefined;
+    export function setAugmenter(augmenter: Augmenter): void {
+        logContextAugmenter = augmenter;
+    }
     export function from(params: { userId?: string; user?: any; request?: any }) {
         return <LogContext>{
             sessionId: params.request?.requestID,
@@ -306,6 +316,7 @@ function makeLogItem(
     if (context !== undefined && Object.keys(context).length == 0) {
         context = undefined;
     }
+    context = logContextAugmenter(context);
     context = scrubPayload(context, plainLogging);
 
     let reportedErrorEvent: {} = {};

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

@@ -0,0 +1,38 @@
+/**
+ * Copyright (c) 2023 Gitpod GmbH. All rights reserved.
+ * Licensed under the GNU Affero General Public License (AGPL).
+ * See License.AGPL.txt in the project root for license information.
+ */
+
+import { LogContext } from "@gitpod/gitpod-protocol/lib/util/logging";
+import { AsyncLocalStorage } from "node:async_hooks";
+import { v4 } from "uuid";
+
+// 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;
+};
+const asyncLocalStorage = new AsyncLocalStorage<EnhancedLogContext>();
+const augmenter: LogContext.Augmenter = (ctx) => {
+    const globalContext = asyncLocalStorage.getStore();
+    const contextTime = globalContext?.contextTimeMs ? Date.now() - globalContext.contextTimeMs : undefined;
+    return {
+        ...globalContext,
+        contextTime,
+        ...ctx,
+    };
+};
+LogContext.setAugmenter(augmenter);
+
+export async function runWithContext<T>(context: LogContext, fun: () => T): Promise<T> {
+    return asyncLocalStorage.run(
+        {
+            ...context,
+            contextId: v4(),
+            contextTimeMs: Date.now(),
+        },
+        fun,
+    );
+}

components/server/src/websocket/websocket-connection-manager.ts

@@ -49,6 +49,7 @@ import * as opentracing from "opentracing";
 import { TraceContext } from "@gitpod/gitpod-protocol/lib/util/tracing";
 import { GitpodHostUrl } from "@gitpod/gitpod-protocol/lib/util/gitpod-host-url";
 import { maskIp } from "../analytics";
+import { runWithContext } from "../util/log-context";
 
 export type GitpodServiceFactory = () => GitpodServerImpl;
 
@@ -373,6 +374,18 @@ class GitpodJsonRpcProxyFactory<T extends object> extends JsonRpcProxyFactory<T>
     }
 
     protected async onRequest(method: string, ...args: any[]): Promise<any> {
+        const userId = this.clientMetadata.userId;
+        return runWithContext(
+            {
+                userId,
+            },
+            () => {
+                return this.internalOnRequest(method, ...args);
+            },
+        );
+    }
+
+    private async internalOnRequest(method: string, ...args: any[]): Promise<any> {
         const span = TraceContext.startSpan(method, undefined);
         const ctx = { span };
         const userId = this.clientMetadata.userId;