diff --git a/packages/common-aws/package.json b/packages/common-aws/package.json index 29fecb5..6ffcaf3 100644 --- a/packages/common-aws/package.json +++ b/packages/common-aws/package.json @@ -1,6 +1,6 @@ { "name": "@paradoxical-io/common-aws", - "version": "2.5.0", + "version": "2.5.1", "description": "Common aws for paradox services", "main": "./dist/index.js", "types": "./dist/index.d.ts", diff --git a/packages/common-hapi/package.json b/packages/common-hapi/package.json index a3e553c..47c7921 100644 --- a/packages/common-hapi/package.json +++ b/packages/common-hapi/package.json @@ -1,6 +1,6 @@ { "name": "@paradoxical-io/common-hapi", - "version": "2.5.0", + "version": "2.5.1", "description": "Common hapi code for paradoxical services", "files": [ "dist/**/*.js", diff --git a/packages/common-server/package.json b/packages/common-server/package.json index a02eaec..224a7c6 100644 --- a/packages/common-server/package.json +++ b/packages/common-server/package.json @@ -1,6 +1,6 @@ { "name": "@paradoxical-io/common-server", - "version": "2.5.0", + "version": "2.5.1", "description": "Common code for paradox services", "main": "./dist/index.js", "types": "./dist/index.d.ts", diff --git a/packages/common-server/src/metrics/metrics.test.ts b/packages/common-server/src/metrics/metrics.test.ts index 8c9ce53..5f23455 100644 --- a/packages/common-server/src/metrics/metrics.test.ts +++ b/packages/common-server/src/metrics/metrics.test.ts @@ -1,17 +1,33 @@ +/* eslint-disable no-console,@typescript-eslint/no-explicit-any */ // make sure we allow all logging (even if the test runner says otherwise) +process.env.PARADOX_LOG_LEVEL = 'info'; + +// ensure log decorators always run +process.env.PARADOX_SKIP_LOG_DECORATORS = 'false'; + import { metricsProvider, timed as timedRaw } from '@paradoxical-io/common'; -import { extendJest } from '@paradoxical-io/common-test'; +import { extendJest, safeExpect } from '@paradoxical-io/common-test'; import { logMethod } from '../logger'; import { Metrics } from './metrics'; import { timed } from './timingDecorator'; -process.env.PARADOX_LOG_LEVEL = 'info'; +extendJest(); -// ensure log decorators always run -process.env.PARADOX_SKIP_LOG_DECORATORS = 'false'; +class TestWithInvalidMetricsType { + @metricsProvider + // @ts-ignore + private _custom: any; -extendJest(); + constructor(custom: any) { + this._custom = custom; + } + + @timedRaw({ stat: 'test_stat_async', tags: { test: 'true' } }) + foo(): Promise { + return Promise.resolve(2); + } +} class TestWithCustomDefault { @metricsProvider @@ -136,3 +152,39 @@ test('timing with annotation plays nicely with logging annotation reverse', asyn expect(Metrics.instance.mockBuffer?.[1].includes('name:Test.timeAndLog')).toBeTruthy(); expect(Metrics.instance.mockBuffer?.[0]).toEqual('log.level:1|c|#level:info'); }); + +test('invalid metrics type allows for method to process', async () => { + const result = await new TestWithInvalidMetricsType('not an object').foo(); + + safeExpect(result).toEqual(2); +}); + +test('invalid metric object type allows for method to process', async () => { + console.log = jest.fn(); + + // make sure there is a class JUST for this test since we are logging that we only want to log once per class + const UniqueClass = class extends TestWithInvalidMetricsType {}; + const result = await new UniqueClass({}).foo(); + const result2 = await new UniqueClass({}).foo(); + + safeExpect(result).toEqual(2); + safeExpect(result2).toEqual(2); + + safeExpect(console.log).toHaveBeenCalledTimes(1); +}); + +test('invalid metric object with type that isnt correct type allows for method to process', async () => { + const result = await new TestWithInvalidMetricsType({ + timing: 'foo', + }).foo(); + + safeExpect(result).toEqual(2); +}); + +test('invalid metric object with type that is missing arguments allows for method to process', async () => { + const result = await new TestWithInvalidMetricsType({ + timing: () => {}, + }).foo(); + + safeExpect(result).toEqual(2); +}); diff --git a/packages/common-sql/package.json b/packages/common-sql/package.json index d0d5121..7716b51 100644 --- a/packages/common-sql/package.json +++ b/packages/common-sql/package.json @@ -1,6 +1,6 @@ { "name": "@paradoxical-io/common-sql", - "version": "2.5.0", + "version": "2.5.1", "files": [ "dist/**/*.js", "dist/**/*.d.ts", diff --git a/packages/common-test/package.json b/packages/common-test/package.json index 616f056..f0ed605 100644 --- a/packages/common-test/package.json +++ b/packages/common-test/package.json @@ -1,6 +1,6 @@ { "name": "@paradoxical-io/common-test", - "version": "2.5.0", + "version": "2.5.1", "description": "Common test-code for jest", "files": [ "dist/**/*.js", diff --git a/packages/common/package.json b/packages/common/package.json index 59656b3..4094aa9 100644 --- a/packages/common/package.json +++ b/packages/common/package.json @@ -1,6 +1,6 @@ { "name": "@paradoxical-io/common", - "version": "2.5.0", + "version": "2.5.1", "description": "Common code for all paradox projects", "files": [ "dist/**/*.js", diff --git a/packages/common/src/decorators/log.test.ts b/packages/common/src/decorators/log.test.ts index 005e1b5..60f0cd5 100644 --- a/packages/common/src/decorators/log.test.ts +++ b/packages/common/src/decorators/log.test.ts @@ -1,5 +1,7 @@ /* eslint-disable @typescript-eslint/no-unused-vars */ // make sure we allow all logging (even if the test runner says otherwise) +import { safeExpect } from '@paradoxical-io/common-test'; + import { Logger, loggingProvider, logMethod } from './logDecorator'; process.env.PARADOX_LOG_LEVEL = 'info'; @@ -30,17 +32,39 @@ class FooCustomLogPropertyName { } } +class FooCustomLogPropertyWrongTypeName { + @loggingProvider + // @ts-ignore + private readonly loggerFancy = 1; + + @logMethod() + getFoo(a: string): void {} +} + test.each([new Foo(), new FooCustomLogPropertyName()])('annotations log with a custom console logger', instance => { const spy = jest.spyOn(process.stdout, 'write'); instance.getFoo('yes'); const log = spy.mock.calls[0][0].toString(); - expect(log).toContain(`start: ${instance.constructor.name}.getFoo("yes")`); - expect(log).toContain(`method: '${instance.constructor.name}.getFoo'`); - expect(log).toContain(`className: '${instance.constructor.name}'`); - expect(log).toContain(`methodAction: 'start'`); + safeExpect(log).toContain(`start: ${instance.constructor.name}.getFoo("yes")`); + safeExpect(log).toContain(`method: '${instance.constructor.name}.getFoo'`); + safeExpect(log).toContain(`className: '${instance.constructor.name}'`); + safeExpect(log).toContain(`methodAction: 'start'`); const end = spy.mock.calls[1][0].toString(); - expect(end).toContain(`end: ${instance.constructor.name}.getFoo, succeeded=true`); + safeExpect(end).toContain(`end: ${instance.constructor.name}.getFoo, succeeded=true`); +}); + +test('annotations do not log when the logger is of the wrong type', () => { + const instance = new FooCustomLogPropertyWrongTypeName(); + const instance2 = new FooCustomLogPropertyWrongTypeName(); + const spy = jest.spyOn(process.stdout, 'write'); + + instance.getFoo('yes'); + instance2.getFoo('yes'); + safeExpect(spy).toHaveBeenCalledTimes(1); + safeExpect(spy.mock.calls[0][0].toString()).toContain( + 'No logging instance could be resolved for timed decorator on class FooCustomLogPropertyWrongTypeName' + ); }); diff --git a/packages/common/src/decorators/logDecorator.ts b/packages/common/src/decorators/logDecorator.ts index 0cca056..5d1a1cf 100644 --- a/packages/common/src/decorators/logDecorator.ts +++ b/packages/common/src/decorators/logDecorator.ts @@ -57,7 +57,11 @@ function resolveLogger(target: object): Logger | undefined { // @ts-ignore const existsLoggerProperty = target[loggingPropertyKey]; - if (existsLoggerProperty) { + if ( + existsLoggerProperty && + typeof existsLoggerProperty === 'object' && + typeof existsLoggerProperty.info === 'function' + ) { return existsLoggerProperty as Logger; } @@ -137,6 +141,7 @@ export function logMethod({ const originalMethod = descriptor!.value; + const warningsByClass = new Set(); // editing the descriptor/value parameter descriptor!.value = function () { const sensitiveParameters: SensitiveMetadata = Reflect.getOwnMetadata(sensitiveMetadata, target, method); @@ -174,9 +179,19 @@ export function logMethod({ canLog = chance({ percentage: samplePercent }); } - const resolvedLogger: Logger | undefined = canLog ? resolveLogger(this) ?? logger : undefined; + const resolvedLogger: Logger | undefined = resolveLogger(this) ?? logger; + + const loggingEnabled = canLog && resolvedLogger; + + const warningWasLogged = warningsByClass.has(this.constructor.name); + if (!loggingEnabled) { + // only log once + if (!process.env.PARADOX_QUIET_TIMING_DECORATORS_EXCEPTIONS && !warningWasLogged && !resolvedLogger) { + // eslint-disable-next-line no-console + console.log(`No logging instance could be resolved for timed decorator on class ${this.constructor.name}`); + warningsByClass.add(this.constructor.name); + } - if (!resolvedLogger) { return originalMethod.apply(this, arguments); } diff --git a/packages/common/src/decorators/timingDecorator.ts b/packages/common/src/decorators/timingDecorator.ts index 186c8f0..710231c 100644 --- a/packages/common/src/decorators/timingDecorator.ts +++ b/packages/common/src/decorators/timingDecorator.ts @@ -18,7 +18,13 @@ function resolveMetrics(target: object): Metrics | undefined { const property = Reflect.getMetadata(customMetrics, target) ?? 'metrics'; // @ts-ignore - return target?.[property] as Metrics; + const metrics = target?.[property] as Metrics; + + if (metrics && typeof metrics === 'object' && typeof metrics.timing === 'function') { + return metrics; + } + + return undefined; } /** @@ -52,17 +58,35 @@ export function timed({ const originalMethod = descriptor!.value; + const warningsByClass = new Set(); // editing the descriptor/value parameter descriptor!.value = function () { const resolvedMetrics: Metrics | undefined = metrics ?? resolveMetrics(this); + const logged = warningsByClass.has(this.constructor.name); + // only log once + if (resolvedMetrics === undefined && !process.env.PARADOX_QUIET_TIMING_DECORATORS_EXCEPTIONS && !logged) { + // eslint-disable-next-line no-console + console.log(`No metrics instance could be resolved for timed decorator on class ${this.constructor.name}`); + warningsByClass.add(this.constructor.name); + } + const start = preciseTimeMilli(); const timingResult = () => { - resolvedMetrics?.timing(metricName, preciseTimeMilli() - start, { - ...tags, - name: `${target.constructor?.name}.${method}`, - }); + try { + resolvedMetrics?.timing(metricName, preciseTimeMilli() - start, { + ...tags, + name: `${target.constructor?.name}.${method}`, + }); + } catch (e: unknown) { + if (process.env.PARADOX_QUIET_TIMING_DECORATORS_EXCEPTIONS) { + // swallow + } else { + // eslint-disable-next-line no-console + console.error('Error emitting timing metric', e); + } + } }; // apply the method diff --git a/packages/types/package.json b/packages/types/package.json index 40d0cbb..a383594 100644 --- a/packages/types/package.json +++ b/packages/types/package.json @@ -1,6 +1,6 @@ { "name": "@paradoxical-io/types", - "version": "2.5.0", + "version": "2.5.1", "description": "Paradox shared types", "files": [ "dist/**/*.js",