From 7f9d889aaea5d5c06a7d814419827f90666b448d Mon Sep 17 00:00:00 2001 From: Anton Kosyakov Date: Mon, 2 Oct 2023 14:36:31 +0000 Subject: [PATCH 1/5] [public-api] add request context --- components/server/src/api/server.ts | 55 +++++++++++++++++++---- components/server/src/server.ts | 2 +- components/server/src/util/log-context.ts | 4 +- 3 files changed, 50 insertions(+), 11 deletions(-) diff --git a/components/server/src/api/server.ts b/components/server/src/api/server.ts index e9ccfa2ea9f1a1..9b38f5bf3a5223 100644 --- a/components/server/src/api/server.ts +++ b/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 { runWithContext } from "../util/log-context"; +import { v4 } from "uuid"; +import { performance } from "perf_hooks"; function service(type: T, impl: ServiceImpl): [T, ServiceImpl] { 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(type: T): ProxyHandler> { @@ -123,6 +126,8 @@ export class API { grpc_type = "bidi_stream"; } + const 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) => { @@ -134,25 +139,59 @@ export class API { 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); + err = ConnectError.from( + `Oops! Something went wrong. Please quote the request ID ${requestId} when reaching out to Gitpod Support.`, + Code.Internal, + ); } done(err); throw err; }; + let verifyDuration: number | undefined; const context = args[1] as HandlerContext; - async function call(): Promise { + function withRequestContext( + target: Function, + thisArgument: any, + argumentsList: ArrayLike, + ): T { + return runWithContext( + "public-api", + { + userId: context.user?.id, + requestId, + grpc_service, + grpc_method, + verifyDuration, + }, + () => Reflect.apply(target, thisArgument, argumentsList), + ); + } + + async function apply(): Promise { + const verifyStartedAt = performance.now(); const user = await self.verify(context); + verifyDuration = performance.now() - verifyStartedAt; context.user = user; - return (target[prop as any] as Function).apply(target, args); + if (grpc_type === "unary" || grpc_type === "client_stream") { + return withRequestContext(target[prop as any], target, args); + } + const generator = withRequestContext(target[prop as any], target, args) as AsyncGenerator; + return (>{ + next: () => withRequestContext(generator.next, generator, []), + return: (value) => withRequestContext(generator.return, generator, [value]), + throw: (e) => withRequestContext(generator.throw, generator, [e]), + + [Symbol.asyncIterator]() { + return this; + }, + }) as any as T; } if (grpc_type === "unary" || grpc_type === "client_stream") { return (async () => { try { - const promise = await call>(); + const promise = await apply>(); const result = await promise; done(); return result; @@ -163,7 +202,7 @@ export class API { } return (async function* () { try { - const generator = await call>(); + const generator = await apply>(); for await (const item of generator) { yield item; } diff --git a/components/server/src/server.ts b/components/server/src/server.ts index 28e351df2cab2f..38611c1ca45c76 100644 --- a/components/server/src/server.ts +++ b/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); } diff --git a/components/server/src/util/log-context.ts b/components/server/src/util/log-context.ts index 6307e22568b1d9..96e3e72db10062 100644 --- a/components/server/src/util/log-context.ts +++ b/components/server/src/util/log-context.ts @@ -30,11 +30,11 @@ const augmenter: LogContext.Augmenter = (ctx) => { }; LogContext.setAugmenter(augmenter); -export async function runWithContext( +export function runWithContext( contextKind: string, context: LogContext & { contextId?: string } & any, fun: () => T, -): Promise { +): T { return asyncLocalStorage.run( { ...context, From 22be512cbc9a3d4a94e6858d2b35c7979ecf6103 Mon Sep 17 00:00:00 2001 From: Anton Kosyakov Date: Mon, 2 Oct 2023 15:08:54 +0000 Subject: [PATCH 2/5] fix metrics and trace public api calls --- components/dashboard/src/service/metrics.ts | 3 +-- components/server/src/api/server.ts | 21 ++++++++++++++++++--- 2 files changed, 19 insertions(+), 5 deletions(-) diff --git a/components/dashboard/src/service/metrics.ts b/components/dashboard/src/service/metrics.ts index 2090603df441d7..1c1d16e4fb5e35 100644 --- a/components/dashboard/src/service/metrics.ts +++ b/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: { diff --git a/components/server/src/api/server.ts b/components/server/src/api/server.ts index 9b38f5bf3a5223..89930599862012 100644 --- a/components/server/src/api/server.ts +++ b/components/server/src/api/server.ts @@ -104,10 +104,11 @@ export class API { return { get(target, prop) { return (...args: any[]) => { + const startedAt = performance.now(); const method = type.methods[prop as any]; if (!method) { // Increment metrics for unknown method attempts - console.warn("public api: unknown method", grpc_service, prop); + log.warn("public api: unknown method", grpc_service, prop); const code = Code.Unimplemented; grpcServerStarted.labels(grpc_service, "unknown", "unknown").inc(); grpcServerHandled.labels(grpc_service, "unknown", "unknown", Code[code]).inc(); @@ -134,11 +135,24 @@ export class API { const grpc_code = err ? Code[err.code] : "OK"; grpcServerHandled.labels(grpc_service, grpc_method, grpc_type, grpc_code).inc(); stopTimer({ grpc_code }); + let callDuration; + if (callStartedAt) { + callDuration = performance.now() - callStartedAt; + } + withRequestContext(log.debug, log, [ + "public api: done", + { + grpc_code, + duration: performance.now() - startedAt, + verifyDuration, + callDuration, + }, + ]); }; 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); + withRequestContext(log.error, log, [`public api: unexpected internal error`, reason]); err = ConnectError.from( `Oops! Something went wrong. Please quote the request ID ${requestId} when reaching out to Gitpod Support.`, Code.Internal, @@ -149,6 +163,7 @@ export class API { }; let verifyDuration: number | undefined; + let callStartedAt: number | undefined; const context = args[1] as HandlerContext; function withRequestContext( target: Function, @@ -162,7 +177,6 @@ export class API { requestId, grpc_service, grpc_method, - verifyDuration, }, () => Reflect.apply(target, thisArgument, argumentsList), ); @@ -174,6 +188,7 @@ export class API { verifyDuration = performance.now() - verifyStartedAt; context.user = user; + callStartedAt = performance.now(); if (grpc_type === "unary" || grpc_type === "client_stream") { return withRequestContext(target[prop as any], target, args); } From 4eaa2446d1e2658ead42d8e6b5088860688f726a Mon Sep 17 00:00:00 2001 From: Anton Kosyakov Date: Wed, 4 Oct 2023 11:19:27 +0000 Subject: [PATCH 3/5] fix context --- components/server/src/api/server.ts | 124 ++++++++++------------ components/server/src/util/log-context.ts | 39 +++++-- 2 files changed, 83 insertions(+), 80 deletions(-) diff --git a/components/server/src/api/server.ts b/components/server/src/api/server.ts index 89930599862012..b02311b65d4c2d 100644 --- a/components/server/src/api/server.ts +++ b/components/server/src/api/server.ts @@ -24,7 +24,7 @@ import { APIStatsService } from "./stats"; import { APITeamsService } from "./teams"; import { APIUserService } from "./user"; import { APIWorkspacesService } from "./workspaces"; -import { runWithContext } from "../util/log-context"; +import { LogContextOptions, wrapAsyncGenerator, runWithContext } from "../util/log-context"; import { v4 } from "uuid"; import { performance } from "perf_hooks"; @@ -104,11 +104,22 @@ export class API { return { get(target, prop) { return (...args: any[]) => { - const startedAt = performance.now(); - 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 = (fn: () => T): T => runWithContext("public-api", logContext, fn); + + const method = type.methods[prop as string]; if (!method) { // Increment metrics for unknown method attempts - log.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(); @@ -127,82 +138,54 @@ export class API { grpc_type = "bidi_stream"; } - const requestId = v4(); + 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 callDuration; - if (callStartedAt) { - callDuration = performance.now() - callStartedAt; - } - withRequestContext(log.debug, log, [ - "public api: done", - { - grpc_code, - duration: performance.now() - startedAt, - verifyDuration, - callDuration, - }, - ]); - }; - const handleError = (reason: unknown) => { - let err = ConnectError.from(reason, Code.Internal); - if (reason != err && err.code === Code.Internal) { - withRequestContext(log.error, log, [`public api: unexpected internal error`, reason]); - err = ConnectError.from( - `Oops! Something went wrong. Please quote the request ID ${requestId} when reaching out to Gitpod Support.`, - Code.Internal, - ); - } - done(err); - throw err; - }; + const done = (err?: ConnectError) => + withRequestContext(() => { + 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) => + withRequestContext(() => { + let err = ConnectError.from(reason, Code.Internal); + if (reason != err && err.code === 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 verifyDuration: number | undefined; + let verifyMs: number | undefined; let callStartedAt: number | undefined; const context = args[1] as HandlerContext; - function withRequestContext( - target: Function, - thisArgument: any, - argumentsList: ArrayLike, - ): T { - return runWithContext( - "public-api", - { - userId: context.user?.id, - requestId, - grpc_service, - grpc_method, - }, - () => Reflect.apply(target, thisArgument, argumentsList), - ); - } - async function apply(): Promise { + const apply = async (): Promise => { const verifyStartedAt = performance.now(); - const user = await self.verify(context); - verifyDuration = performance.now() - verifyStartedAt; + const user = await withRequestContext(() => self.verify(context)); + verifyMs = performance.now() - verifyStartedAt; context.user = user; callStartedAt = performance.now(); - if (grpc_type === "unary" || grpc_type === "client_stream") { - return withRequestContext(target[prop as any], target, args); - } - const generator = withRequestContext(target[prop as any], target, args) as AsyncGenerator; - return (>{ - next: () => withRequestContext(generator.next, generator, []), - return: (value) => withRequestContext(generator.return, generator, [value]), - throw: (e) => withRequestContext(generator.throw, generator, [e]), - - [Symbol.asyncIterator]() { - return this; - }, - }) as any as T; - } + return withRequestContext(() => Reflect.apply(target[prop as any], target, args)); + }; if (grpc_type === "unary" || grpc_type === "client_stream") { return (async () => { try { @@ -217,7 +200,8 @@ export class API { } return (async function* () { try { - const generator = await apply>(); + let generator = await apply>(); + generator = wrapAsyncGenerator(generator, withRequestContext); for await (const item of generator) { yield item; } diff --git a/components/server/src/util/log-context.ts b/components/server/src/util/log-context.ts index 96e3e72db10062..a88dad8b316368 100644 --- a/components/server/src/util/log-context.ts +++ b/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(); 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 function runWithContext( - contextKind: string, - context: LogContext & { contextId?: string } & any, - fun: () => T, -): T { +export function runWithContext(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 = (f: () => T) => T; +export function wrapAsyncGenerator( + generator: AsyncGenerator, + decorator: AsyncGeneratorDecorator, +): AsyncGenerator { + return >{ + next: () => decorator(() => generator.next()), + return: (value?: any) => decorator(() => generator.return(value)), + throw: (e?: any) => decorator(() => generator.throw(e)), + + [Symbol.asyncIterator]() { + return this; + }, + }; +} From 864038aca63046f480a35c34d90daa1cf937fc4d Mon Sep 17 00:00:00 2001 From: Anton Kosyakov Date: Wed, 4 Oct 2023 11:37:34 +0000 Subject: [PATCH 4/5] simplify --- components/server/src/api/server.ts | 90 ++++++++++++++--------------- 1 file changed, 45 insertions(+), 45 deletions(-) diff --git a/components/server/src/api/server.ts b/components/server/src/api/server.ts index b02311b65d4c2d..3b242eb969637c 100644 --- a/components/server/src/api/server.ts +++ b/components/server/src/api/server.ts @@ -142,36 +142,34 @@ export class API { grpcServerStarted.labels(grpc_service, grpc_method, grpc_type).inc(); const stopTimer = grpcServerHandling.startTimer({ grpc_service, grpc_method, grpc_type }); - const done = (err?: ConnectError) => - withRequestContext(() => { - 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) => - withRequestContext(() => { - let err = ConnectError.from(reason, Code.Internal); - if (reason != err && err.code === 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; - }); + 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) { + 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; @@ -179,15 +177,15 @@ export class API { const apply = async (): Promise => { const verifyStartedAt = performance.now(); - const user = await withRequestContext(() => self.verify(context)); + const user = await self.verify(context); verifyMs = performance.now() - verifyStartedAt; context.user = user; callStartedAt = performance.now(); - return withRequestContext(() => Reflect.apply(target[prop as any], target, args)); + 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 apply>(); const result = await promise; @@ -196,20 +194,22 @@ export class API { } catch (e) { handleError(e); } - })(); + }); } - return (async function* () { - try { - let generator = await apply>(); - generator = wrapAsyncGenerator(generator, withRequestContext); - for await (const item of generator) { - yield item; + return wrapAsyncGenerator( + (async function* () { + try { + const generator = await apply>(); + for await (const item of generator) { + yield item; + } + done(); + } catch (e) { + handleError(e); } - done(); - } catch (e) { - handleError(e); - } - })(); + })(), + withRequestContext, + ); }; }, }; From 5e505fcf2ec917da19984d63501a4a20d4e3fca0 Mon Sep 17 00:00:00 2001 From: Anton Kosyakov Date: Wed, 4 Oct 2023 12:08:31 +0000 Subject: [PATCH 5/5] fix server side streams --- components/server/src/api/dummy.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/components/server/src/api/dummy.ts b/components/server/src/api/dummy.ts index 7c5874ab7c60f0..073611729ab916 100644 --- a/components/server/src/api/dummy.ts +++ b/components/server/src/api/dummy.ts @@ -24,7 +24,7 @@ export class APIHelloService implements ServiceImpl { } async *lotsOfReplies(req: LotsOfRepliesRequest, context: HandlerContext): AsyncGenerator { 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;