fix: properly bind observables and promise results in case of errors

ref: #1741
jmcdo29 · Aug 6, 2023 · 12a6709 · 12a6709
1 parent fe79f5e
commit 12a6709
Show file tree

Hide file tree

Showing 4 changed files with 112 additions and 31 deletions.
diff --git a/integration/test/log-decorator.spec.ts b/integration/test/log-decorator.spec.ts
@@ -9,7 +9,7 @@ import {
   OgmaService,
 } from '@ogma/nestjs-module';
 import { Stub, stubMethod } from 'hanbi';
-import { delay, of } from 'rxjs';
+import { delay, of, switchMap, take, throwError, timer } from 'rxjs';
 import { suite } from 'uvu';
 import { is, match } from 'uvu/assert';
 
@@ -31,6 +31,24 @@ class TestService {
   testMethodRxJs() {
     return of('hello').pipe(delay(200));
   }
+
+  @Log()
+  testMethodError() {
+    throw new Error('Boom!');
+  }
+
+  @Log()
+  testAsyncMethodError() {
+    return new Promise((_resolve, reject) => setTimeout(() => reject(new Error('Boom!')), 300));
+  }
+
+  @Log()
+  testMethodErrorRxJs() {
+    return timer(200).pipe(
+      take(1),
+      switchMap(() => throwError(() => new Error('Boom!'))),
+    );
+  }
 }
 
 @Injectable()
@@ -62,10 +80,8 @@ LogDecoratorSuite.before(async (context) => {
   const mod = await Test.createTestingModule({
     imports: [
       OgmaModule.forRoot({
-        service: {
-          application: 'LogDecorator',
-          logLevel: 'ALL',
-        },
+        application: 'LogDecorator',
+        logLevel: 'ALL',
       }),
       OgmaModule.forFeatures(['TestService', 'TestLogAllService']),
     ],
@@ -112,6 +128,47 @@ LogDecoratorSuite('rxjs log call', async ({ testServiceLogSpy, testService }) =>
   });
 });
 
+LogDecoratorSuite('sync error method log call', ({ testServiceLogSpy, testService }) => {
+  try {
+    testService.testMethodError();
+  } catch {
+    is(testServiceLogSpy.callCount, 2);
+    is(testServiceLogSpy.firstCall.args[0], 'Start testMethodError');
+    match(testServiceLogSpy.lastCall.args[0], /End testMethodError - \d+ms/);
+  }
+});
+
+LogDecoratorSuite('async error method log call', async ({ testServiceLogSpy, testService }) => {
+  await testService.testAsyncMethodError().catch(() => {
+    is(testServiceLogSpy.callCount, 2);
+    is(testServiceLogSpy.firstCall.args[0], 'Start testAsyncMethodError');
+    match(testServiceLogSpy.lastCall.args[0], /End testAsyncMethodError - \d+ms/);
+  });
+});
+
+LogDecoratorSuite('rxjs error log call', async ({ testServiceLogSpy, testService }) => {
+  let wasAsserted = false;
+  return new Promise((resolve, reject) => {
+    testService.testMethodErrorRxJs().subscribe({
+      error: () => {
+        is(testServiceLogSpy.callCount, 2);
+        is(testServiceLogSpy.firstCall.args[0], 'Start testMethodErrorRxJs');
+        match(testServiceLogSpy.lastCall.args[0], /End testMethodErrorRxJs - 2\d{2}ms/);
+        wasAsserted = true;
+        resolve();
+      },
+      complete: () => {
+        is(wasAsserted, true, 'The error hook should have ran for the observable');
+        if (wasAsserted) {
+          resolve();
+        } else {
+          reject();
+        }
+      },
+    });
+  });
+});
+
 LogDecoratorSuite('LogAll method1', ({ testLogAllLogSpy, testLogAllService }) => {
   is(testLogAllService.method1(), 'hello');
   is(testLogAllLogSpy.callCount, 2);

diff --git a/package.json b/package.json
@@ -109,6 +109,7 @@
     "clsx": "^1.2.1",
     "conventional-changelog-cli": "^3.0.0",
     "cz-conventional-changelog": "^3.3.0",
+    "decorate-all": "^1.2.1",
     "eslint": "8.43.0",
     "eslint-config-prettier": "^8.5.0",
     "eslint-plugin-prettier": "^4.2.1",

diff --git a/packages/nestjs-module/src/decorators/ogma-logger.decorator.ts b/packages/nestjs-module/src/decorators/ogma-logger.decorator.ts
@@ -1,5 +1,6 @@
 import { ContextType, Inject } from '@nestjs/common';
-import { isObservable, tap } from 'rxjs';
+import { DecorateAll } from 'decorate-all';
+import { isObservable, Observable, tap } from 'rxjs';
 
 import { AbstractInterceptorService } from '../interceptor/providers';
 import { Type } from '../interfaces';
@@ -13,6 +14,10 @@ export const OgmaLogger = (topic: string | (() => any) | Type<any>) =>
 export const OgmaLoggerRequestScoped = (topic: string | (() => any) | Type<any>) =>
   Inject(createRequestScopedProviderToken(typeof topic === 'function' ? topic.name : topic));
 
+const isPromise = (obj: unknown): obj is Promise<any> => {
+  return typeof obj === 'object' && obj !== null && 'then' in obj && typeof obj.then === 'function';
+};
+
 const logEnd = (
   { context, method }: { context: string; method: string },
   logger: OgmaService,
@@ -32,9 +37,16 @@ export const Log =
       const logger: OgmaService = this[loggerProperty];
       const context = `${target.constructor.name}#${method}`;
       logger.trace(`Start ${method}`, { context });
-      let result = (impl as any).apply(this, args);
-      if (result.then) {
-        result.finally(() => {
+      let result: Promise<unknown> | Observable<unknown> | unknown;
+      try {
+        result = (impl as any).apply(this, args);
+      } finally {
+        if (!(typeof result === 'object' || typeof result === 'function')) {
+          logEnd({ context, method }, logger, start);
+        }
+      }
+      if (isPromise(result)) {
+        return result.finally(() => {
           logEnd({ context, method }, logger, start);
         });
       } else if (isObservable(result)) {
@@ -43,32 +55,20 @@ export const Log =
          * we need to re-assign the `result` back to itself so that the new pipe will be ran
          * with the original observable
          */
-        result = result.pipe(tap({ complete: () => logEnd({ context, method }, logger, start) }));
-      } else {
-        logEnd({ context, method }, logger, start);
+        return result.pipe(
+          tap({
+            error: () => logEnd({ context, method }, logger, start),
+            complete: () => logEnd({ context, method }, logger, start),
+          }),
+        );
       }
       return result;
     } as any;
     return descriptor;
   };
 
-export const LogAll =
-  (loggerProperty = 'logger'): ClassDecorator =>
-  (target) => {
-    const allKeys = Reflect.ownKeys(target.prototype);
-    const keys = allKeys.filter((key) => key !== 'constructor');
-    for (const key of keys) {
-      const logRet = Log(loggerProperty)(
-        target.prototype,
-        key,
-        Reflect.getOwnPropertyDescriptor(target.prototype, key),
-      );
-      if (logRet) {
-        target.prototype[key] = logRet.value;
-      }
-    }
-    return target;
-  };
+export const LogAll = (loggerProperty = 'logger'): ClassDecorator =>
+  DecorateAll(Log(loggerProperty));
 
 type ParserDecorator = <TFunction extends Type<AbstractInterceptorService>>(
   target: TFunction,

diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml