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)

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

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: [

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);
   }
 }
 

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 });

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<GqlContextType>();
+  const req = getRequestFromHost(host);
+  return getRequestIdFromRequest(req, type);
+}

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');