Better safety for wrong types and log messages

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",

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",

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",

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<number> {
+    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);
+});

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",

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",

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",

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

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<string>();
     // 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);
       }
 

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<string>();
     // 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

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",