refactor(server): auto print full stack on logger.error (#10161)

packages/backend/server/src/__tests__/utils/testing-module.ts

@@ -8,7 +8,7 @@ import {
 } from '@nestjs/testing';
 
 import { AppModule, FunctionalityModules } from '../../app.module';
-import { Runtime } from '../../base';
+import { AFFiNELogger, Runtime } from '../../base';
 import { GqlModule } from '../../base/graphql';
 import { AuthGuard, AuthModule } from '../../core/auth';
 import { ModelsModule } from '../../models';
@@ -95,16 +95,15 @@ export async function createTestingModule(
     await module.close();
   };
 
+  const logger = new AFFiNELogger();
+  // we got a lot smoking tests try to break nestjs
+  // can't tolerate the noisy logs
+  logger.setLogLevels([TEST_LOG_LEVEL]);
+  module.useLogger(logger);
+
   if (autoInitialize) {
-    // we got a lot smoking tests try to break nestjs
-    // can't tolerate the noisy logs
-    // @ts-expect-error private
-    module.applyLogger({
-      logger: [TEST_LOG_LEVEL],
-    });
     await testingModule.initTestingDB();
     await testingModule.init();
   }
-
   return testingModule;
 }

packages/backend/server/src/base/error/def.ts

@@ -152,11 +152,7 @@ export class UserFriendlyError extends Error {
     if (debugInfo) {
       message += ` (${JSON.stringify(debugInfo)})`;
     }
-    let stack = this.stack ?? '';
+    fn.call(logger, message, this);
-    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/logger/__tests__/service.spec.ts

@@ -0,0 +1,75 @@
+import { mock } from 'node:test';
+
+import { TestingModule } from '@nestjs/testing';
+import ava, { TestFn } from 'ava';
+
+import { createTestingModule } from '../../../__tests__/utils';
+import { AFFiNELogger } from '../service';
+
+export const test = ava as TestFn<{
+  module: TestingModule;
+  logger: AFFiNELogger;
+}>;
+
+test.before(async t => {
+  const m = await createTestingModule({
+    providers: [AFFiNELogger],
+  });
+  const logger = m.get(AFFiNELogger);
+  t.context.module = m;
+  t.context.logger = logger;
+});
+
+test.afterEach(() => {
+  mock.reset();
+});
+
+test.after(async t => {
+  await t.context.module.close();
+});
+
+test('should auto print error stack when stack argument is an error instance', t => {
+  const logger = t.context.logger;
+  const error = new Error('test error');
+  // @ts-expect-error private method
+  const fake = mock.method(logger, 'printMessages', () => {
+    return;
+  });
+  logger.error('test message', error);
+  t.is(fake.mock.callCount(), 1);
+  const printStackTraceArgs: any = fake.mock.calls[0].arguments[0];
+  t.is(printStackTraceArgs[0], 'test message');
+  t.is(printStackTraceArgs[1], error.stack);
+});
+
+test('should auto print error stack when stack argument is a string', t => {
+  const logger = t.context.logger;
+  const error = new Error('test error');
+  // @ts-expect-error private method
+  const fake = mock.method(logger, 'printMessages', () => {
+    return;
+  });
+  logger.error('test message', error.stack);
+  t.is(fake.mock.callCount(), 1);
+  const printStackTraceArgs: any = fake.mock.calls[0].arguments[0];
+  t.is(printStackTraceArgs[0], 'test message');
+  t.is(printStackTraceArgs[1], error.stack);
+});
+
+test('should print error stack with cause', t => {
+  const logger = t.context.logger;
+  const error = new Error('test error');
+  error.cause = new Error('cause error');
+  // @ts-expect-error private method
+  const fake = mock.method(logger, 'printMessages', () => {
+    return;
+  });
+  logger.error('test message', error);
+  t.is(fake.mock.callCount(), 1);
+  const printStackTraceArgs: any = fake.mock.calls[0].arguments[0];
+  t.is(printStackTraceArgs[0], 'test message');
+  t.is(
+    printStackTraceArgs[1],
+    `${error.stack}\n\nCaused by:\n\n${(error.cause as any).stack}`
+  );
+});

packages/backend/server/src/base/logger/service.ts

@@ -17,4 +17,30 @@ export class AFFiNELogger extends ConsoleLogger {
   static getRequestId(): string | undefined {
     return ClsServiceManager.getClsService()?.getId();
   }
+
+  /**
+   * Nestjs ConsoleLogger.error() will not print the stack trace if the error is an instance of Error
+   * This method is a workaround to print the stack trace
+   *
+   * Usage:
+   * ```
+   * this.logger.error('some error happens', errInstance);
+   * ```
+   */
+  override error(
+    message: any,
+    stackOrError?: Error | string | unknown,
+    context?: string
+  ) {
+    let stack = '';
+    if (stackOrError instanceof Error) {
+      const err = stackOrError;
+      stack = err.stack ?? '';
+      if (err.cause instanceof Error && err.cause.stack) {
+        stack += `\n\nCaused by:\n\n${err.cause.stack}`;
+      }
+      stackOrError = stack;
+    }
+    super.error(message, stackOrError, context);
+  }
 }

packages/backend/server/src/plugins/gcloud/logging/logger.ts

@@ -1,17 +1,13 @@
 import { WinstonLogger } from 'nest-winston';
 
+import { AFFiNELogger as RawAFFiNELogger } from '../../../base/logger';
+
 export class AFFiNELogger extends WinstonLogger {
   override error(
     message: any,
-    trace?: Error | string | unknown,
+    stackOrError?: Error | string | unknown,
     context?: string
   ) {
-    if (trace && trace instanceof Error) {
+    RawAFFiNELogger.prototype.error.call(this, message, stackOrError, context);
-      super.error(message, trace.stack, context);
-    } else if (typeof trace === 'string' || trace === undefined) {
-      super.error(message, trace, context);
-    } else {
-      super.error(message, undefined, context);
-    }
   }
 }