From 0ce4cc860904064b6462e7b50ddf75a2344dfdfe Mon Sep 17 00:00:00 2001 From: fengmk2 Date: Thu, 13 Feb 2025 02:20:02 +0000 Subject: [PATCH] refactor(server): add debug info on global exception log (#10118) before ![image.png](https://graphite-user-uploaded-assets-prod.s3.amazonaws.com/hTwOityLamd4hitrae7M/4fc84ed7-a3a3-452b-85d0-240847793c5c.png) after ![image.png](https://graphite-user-uploaded-assets-prod.s3.amazonaws.com/hTwOityLamd4hitrae7M/60d9342c-6bf2-4ed0-817a-8e4eba3e0832.png) --- .../__tests__/nestjs/error-handler.spec.ts | 8 +++++++- packages/backend/server/src/app.module.ts | 13 ++++++++---- packages/backend/server/src/base/error/def.ts | 16 +++++++++------ .../server/src/base/nestjs/exception.ts | 5 ++++- .../backend/server/src/base/utils/request.ts | 20 ++++++++++++++++--- .../doc-service/__tests__/controller.spec.ts | 2 +- 6 files changed, 48 insertions(+), 16 deletions(-) diff --git a/packages/backend/server/src/__tests__/nestjs/error-handler.spec.ts b/packages/backend/server/src/__tests__/nestjs/error-handler.spec.ts index d8d2ad52c..934473503 100644 --- a/packages/backend/server/src/__tests__/nestjs/error-handler.spec.ts +++ b/packages/backend/server/src/__tests__/nestjs/error-handler.spec.ts @@ -170,7 +170,13 @@ test('should be able to handle unknown internal error in http request', async t .expect(HttpStatus.INTERNAL_SERVER_ERROR); t.is(res.body.message, 'An internal error occurred.'); t.is(res.body.name, 'INTERNAL_SERVER_ERROR'); - t.true(t.context.logger.error.calledOnceWith('internal_server_error')); + t.true( + t.context.logger.error.calledOnceWith( + `internal_server_error (${JSON.stringify({ + requestId: res.body.requestId, + })})` + ) + ); }); // Hard to test through websocket, will call event handler directly diff --git a/packages/backend/server/src/app.module.ts b/packages/backend/server/src/app.module.ts index 3e66bbed8..1eca3ed76 100644 --- a/packages/backend/server/src/app.module.ts +++ b/packages/backend/server/src/app.module.ts @@ -1,5 +1,6 @@ import { DynamicModule, + ExecutionContext, ForwardReference, Logger, Module, @@ -13,7 +14,11 @@ import { get } from 'lodash-es'; import { ClsModule } from 'nestjs-cls'; import { AppController } from './app.controller'; -import { genRequestId, getOptionalModuleMetadata } from './base'; +import { + getOptionalModuleMetadata, + getRequestIdFromHost, + getRequestIdFromRequest, +} from './base'; import { CacheModule } from './base/cache'; import { AFFiNEConfig, ConfigModule, mergeConfigOverride } from './base/config'; import { ErrorModule } from './base/error'; @@ -57,7 +62,7 @@ export const FunctionalityModules = [ generateId: true, idGenerator(req: Request) { // make every request has a unique id to tracing - return req.get('x-cloud-trace-context') ?? genRequestId('req'); + return getRequestIdFromRequest(req, 'http'); }, setup(cls, _req, res: Response) { res.setHeader('X-Request-Id', cls.getId()); @@ -68,9 +73,9 @@ export const FunctionalityModules = [ interceptor: { mount: true, generateId: true, - idGenerator() { + idGenerator(context: ExecutionContext) { // make every request has a unique id to tracing - return genRequestId('ws'); + return getRequestIdFromHost(context); }, }, plugins: [ diff --git a/packages/backend/server/src/base/error/def.ts b/packages/backend/server/src/base/error/def.ts index 52aafcec7..908167a02 100644 --- a/packages/backend/server/src/base/error/def.ts +++ b/packages/backend/server/src/base/error/def.ts @@ -136,7 +136,7 @@ export class UserFriendlyError extends Error { ].join('\n'); } - log(context: string) { + log(context: string, debugInfo?: object) { // ignore all user behavior error log if ( this.type !== 'internal_server_error' && @@ -148,11 +148,15 @@ export class UserFriendlyError extends Error { const logger = new Logger(context); const fn = this.status >= 500 ? logger.error : logger.log; - fn.call( - logger, - this.name, - this.cause ? ((this.cause as any).stack ?? this.cause) : this.stack - ); + let message = this.name; + if (debugInfo) { + message += ` (${JSON.stringify(debugInfo)})`; + } + let stack = this.stack ?? ''; + if (this.cause) { + stack += `\n\nCaused by:\n\n${(this.cause as any).stack ?? this.cause}`; + } + fn.call(logger, message, stack); } } diff --git a/packages/backend/server/src/base/nestjs/exception.ts b/packages/backend/server/src/base/nestjs/exception.ts index 001c73415..3b1cf06ff 100644 --- a/packages/backend/server/src/base/nestjs/exception.ts +++ b/packages/backend/server/src/base/nestjs/exception.ts @@ -19,6 +19,7 @@ import { UserFriendlyError, } from '../error'; import { metrics } from '../metrics'; +import { getRequestIdFromHost } from '../utils'; export function mapAnyError(error: any): UserFriendlyError { if (error instanceof UserFriendlyError) { @@ -45,7 +46,9 @@ export class GlobalExceptionFilter extends BaseExceptionFilter { // see '../graphql/logger-plugin.ts' throw error; } else { - error.log('HTTP'); + error.log('HTTP', { + requestId: error.requestId ?? getRequestIdFromHost(host), + }); metrics.controllers .counter('error') .add(1, { status: error.status, type: error.type, error: error.name }); diff --git a/packages/backend/server/src/base/utils/request.ts b/packages/backend/server/src/base/utils/request.ts index 723767a6d..80b1aa503 100644 --- a/packages/backend/server/src/base/utils/request.ts +++ b/packages/backend/server/src/base/utils/request.ts @@ -84,16 +84,17 @@ export function parseCookies( * Request type * * @description - * - `req`: http request + * - `graphql`: graphql request + * - `http`: http request * - `ws`: websocket request * - `se`: server event * - `job`: cron job * - `rpc`: rpc request */ -export type RequestType = 'req' | 'ws' | 'se' | 'job' | 'rpc'; +export type RequestType = GqlContextType | 'se' | 'job'; export function genRequestId(type: RequestType) { - return `${AFFiNE.flavor.type}:${type}-${randomUUID()}`; + return `${AFFiNE.flavor.type}:${type}/${randomUUID()}`; } export function getOrGenRequestId(type: RequestType) { @@ -101,3 +102,16 @@ export function getOrGenRequestId(type: RequestType) { // but it can be lost in unexpected scenarios, such as unit tests, where it is automatically generated. return ClsServiceManager.getClsService()?.getId() ?? genRequestId(type); } + +export function getRequestIdFromRequest(req: Request, type: RequestType) { + const traceContext = req.headers['x-cloud-trace-context'] as string; + const traceId = traceContext ? traceContext.split('/', 1)[0] : undefined; + if (traceId) return traceId; + return genRequestId(type); +} + +export function getRequestIdFromHost(host: ArgumentsHost) { + const type = host.getType(); + const req = getRequestFromHost(host); + return getRequestIdFromRequest(req, type); +} diff --git a/packages/backend/server/src/core/doc-service/__tests__/controller.spec.ts b/packages/backend/server/src/core/doc-service/__tests__/controller.spec.ts index 581bf5468..a4cb646a7 100644 --- a/packages/backend/server/src/core/doc-service/__tests__/controller.spec.ts +++ b/packages/backend/server/src/core/doc-service/__tests__/controller.spec.ts @@ -110,7 +110,7 @@ test('should return doc when found', async t => { const res = await app .GET(`/rpc/workspaces/${workspace.id}/docs/${docId}`) .set('x-access-token', t.context.crypto.sign(docId)) - .set('x-cloud-trace-context', 'test-trace-id') + .set('x-cloud-trace-context', 'test-trace-id/span-id') .expect(200) .expect('x-request-id', 'test-trace-id') .expect('Content-Type', 'application/octet-stream');