From 12a6709419d6641966f84a17f3a36c08a483af65 Mon Sep 17 00:00:00 2001 From: Jay McDoniel Date: Sun, 6 Aug 2023 14:28:21 -0700 Subject: [PATCH] fix: properly bind observables and promise results in case of errors ref: #1741 --- integration/test/log-decorator.spec.ts | 67 +++++++++++++++++-- package.json | 1 + .../src/decorators/ogma-logger.decorator.ts | 48 ++++++------- pnpm-lock.yaml | 27 +++++++- 4 files changed, 112 insertions(+), 31 deletions(-) diff --git a/integration/test/log-decorator.spec.ts b/integration/test/log-decorator.spec.ts index 54c4c802a..589fadcf5 100644 --- 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 index 307ba2b04..94447149c 100644 --- 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 index afccf8c46..86eb3b637 100644 --- 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) => export const OgmaLoggerRequestScoped = (topic: string | (() => any) | Type) => Inject(createRequestScopedProviderToken(typeof topic === 'function' ? topic.name : topic)); +const isPromise = (obj: unknown): obj is Promise => { + 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 | Observable | 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 = >( target: TFunction, diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index ab2e61428..10c4623cf 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -1,4 +1,4 @@ -lockfileVersion: '6.1' +lockfileVersion: '6.0' settings: autoInstallPeers: true @@ -207,6 +207,9 @@ importers: cz-conventional-changelog: specifier: ^3.3.0 version: 3.3.0(@swc/core@1.3.67) + decorate-all: + specifier: ^1.2.1 + version: 1.2.1(reflect-metadata@0.1.13) eslint: specifier: 8.43.0 version: 8.43.0 @@ -411,7 +414,7 @@ importers: specifier: ^9.0.0 || ^10.0.0 version: 10.0.4(@nestjs/common@10.0.4)(@nestjs/microservices@10.0.4)(@nestjs/platform-express@10.0.4)(@nestjs/websockets@10.0.4)(reflect-metadata@0.1.13)(rxjs@7.8.1) '@ogma/logger': - specifier: workspace:^3.1.0 + specifier: workspace:^3.1.2 version: link:../logger '@ogma/styler': specifier: workspace:^1.0.0 @@ -2859,6 +2862,7 @@ packages: /@commitlint/config-validator@17.4.4: resolution: {integrity: sha512-bi0+TstqMiqoBAQDvdEP4AFh0GaKyLFlPPEObgI29utoKEYoPQTvF0EYqIwYYLEoJYhj5GfMIhPHJkTJhagfeg==} engines: {node: '>=v14'} + requiresBuild: true dependencies: '@commitlint/types': 17.4.4 ajv: 8.12.0 @@ -2879,6 +2883,7 @@ packages: /@commitlint/execute-rule@17.4.0: resolution: {integrity: sha512-LIgYXuCSO5Gvtc0t9bebAMSwd68ewzmqLypqI2Kke1rqOqqDbMpYcYfoPfFlv9eyLIh4jocHWwCK5FS7z9icUA==} engines: {node: '>=v14'} + requiresBuild: true dev: true /@commitlint/format@17.4.4: @@ -2958,6 +2963,7 @@ packages: /@commitlint/resolve-extends@17.4.4: resolution: {integrity: sha512-znXr1S0Rr8adInptHw0JeLgumS11lWbk5xAWFVno+HUFVN45875kUtqjrI6AppmD3JI+4s0uZlqqlkepjJd99A==} engines: {node: '>=v14'} + requiresBuild: true dependencies: '@commitlint/config-validator': 17.4.4 '@commitlint/types': 17.4.4 @@ -3799,6 +3805,7 @@ packages: /@jridgewell/source-map@0.3.4: resolution: {integrity: sha512-KE/SxsDqNs3rrWwFHcRh15ZLVFrI0YoZtgAdIyIq9k5hUNmiWRXXThPomIxHuL20sLdgzbDFyvkUMna14bvtrw==} + deprecated: the version has a bug with typescript type resolution dev: true /@jridgewell/sourcemap-codec@1.4.14: @@ -7449,6 +7456,7 @@ packages: /cosmiconfig-typescript-loader@4.3.0(@types/node@18.16.18)(cosmiconfig@8.2.0)(ts-node@10.9.1)(typescript@5.1.3): resolution: {integrity: sha512-NTxV1MFfZDLPiBMjxbHRwSh5LaLcPMwNdCutmnHJCKoVnlvldPWlllonKwrsRJ5pYZBIBGRWWU2tfvzxgeSW5Q==} engines: {node: '>=12', npm: '>=6'} + requiresBuild: true peerDependencies: '@types/node': '*' cosmiconfig: '>=7' @@ -7605,6 +7613,14 @@ packages: mimic-response: 3.1.0 dev: true + /decorate-all@1.2.1(reflect-metadata@0.1.13): + resolution: {integrity: sha512-4lq/hEXS7n+G3J1dRqS10GFd5/xhvPo17a9Dmq+UPWBiHGAv/NcSthI3jZlkxnZCPLc8F+oRzF6h2Cc2ahc5jA==} + peerDependencies: + reflect-metadata: ^0 + dependencies: + reflect-metadata: 0.1.13 + dev: true + /dedent@0.7.0: resolution: {integrity: sha512-Q6fKUPqnAHAyhiUgFU7BUzLiv0kd8saH9al7tnu5Q/okj6dnupxyTgFIBjVzJATdfIAm9NAsvXNzjaKa+bxVyA==} dev: true @@ -9028,6 +9044,7 @@ packages: /glob@6.0.4: resolution: {integrity: sha512-MKZeRNyYZAVVVG1oZeLaWie1uweH40m9AZwIwxyPbTSX4hHrVYSzLg0Ro5Z5R7XKkIX+Cc6oD1rqeDJnwsB8/A==} + requiresBuild: true dependencies: inflight: 1.0.6 inherits: 2.0.4 @@ -9472,6 +9489,7 @@ packages: /iconv-lite@0.6.3: resolution: {integrity: sha512-4fCk79wshMdzMp2rH06qWrJE4iolqLhCUH+OiuIgU++RB0+94NlDL81atO7GX55uUKueo0txHNtvEyI6D7WdMw==} engines: {node: '>=0.10.0'} + requiresBuild: true dependencies: safer-buffer: 2.1.2 dev: true @@ -10666,6 +10684,7 @@ packages: /lodash.isplainobject@4.0.6: resolution: {integrity: sha512-oSXzaWypCMHkPC3NvBEaPHf0KsA5mvPrOPgQWDsbg8n7orZ290M0BmC/jgRZ4vcJ6DTAhjrsSYgdsW/F+MFOBA==} + requiresBuild: true dev: true /lodash.kebabcase@4.1.1: @@ -10706,6 +10725,7 @@ packages: /lodash.uniq@4.5.0: resolution: {integrity: sha512-xfBaXQd9ryd9dlSDvnvI0lvxfLJlYAZzXomUYzLKtUeOQvOP5piqAWuGtrhWeqaXK9hhoM/iyJc5AV+XfsX3HQ==} + requiresBuild: true dev: true /lodash.upperfirst@4.3.1: @@ -11713,6 +11733,7 @@ packages: /nan@2.17.0: resolution: {integrity: sha512-2ZTgtl0nJsO0KQCjEpxcIr5D+Yv90plTitZt9JBfQvVJDS5seMl3FOvsh3+9CoYWXf/1l5OaZzzF6nDm4cagaQ==} + requiresBuild: true dev: true optional: true @@ -11740,6 +11761,7 @@ packages: /ncp@2.0.0: resolution: {integrity: sha512-zIdGUrPRFTUELUvr3Gmc7KZ2Sw/h1PiVM0Af/oHB6zgnV1ikqSfRk+TOufi79aHYCW3NiOXmr1BP5nWbzojLaA==} hasBin: true + requiresBuild: true dev: true optional: true @@ -13126,6 +13148,7 @@ packages: /rimraf@2.4.5: resolution: {integrity: sha512-J5xnxTyqaiw06JjMftq7L9ouA448dw/E7dKghkP9WpKNuwmARNNg+Gk8/u5ryb9N/Yo2+z3MCwuqFK/+qPOPfQ==} hasBin: true + requiresBuild: true dependencies: glob: 6.0.4 dev: true