feat: bind trigger information to all logs (#926)

googleapis · Sep 2, 2020 · dcdd281 · dcdd281
1 parent f2f6c86
commit dcdd281
Show file tree

Hide file tree

Showing 7 changed files with 185 additions and 71 deletions.
diff --git a/packages/gcf-utils/src/gcf-utils.ts b/packages/gcf-utils/src/gcf-utils.ts
@@ -19,7 +19,7 @@ import * as express from 'express';
 // eslint-disable-next-line node/no-extraneous-import
 import {Octokit} from '@octokit/rest';
 import {buildTriggerInfo} from './logging/trigger-info-builder';
-import {GCFLogger, initLogger} from './logging/gcf-logger';
+import {GCFLogger} from './logging/gcf-logger';
 // eslint-disable-next-line @typescript-eslint/no-var-requires
 const LoggingOctokitPlugin = require('../src/logging/logging-octokit-plugin.js');
 
@@ -54,7 +54,7 @@ export interface WrapOptions {
   logging: boolean;
 }
 
-export const logger: GCFLogger = initLogger();
+export const logger = new GCFLogger();
 
 export interface CronPayload {
   repository: {
@@ -200,7 +200,13 @@ export class GCFBootstrapper {
         taskId
       );
 
-      logger.metric(buildTriggerInfo(triggerType, id, name, request.body));
+      /**
+       * Note: any logs written before resetting bindings may contain
+       * bindings from previous executions
+       */
+      logger.resetBindings();
+      logger.addBindings(buildTriggerInfo(triggerType, id, name, request.body));
+      logger.metric(`Execution started by ${triggerType}`);
 
       try {
         if (triggerType === TriggerType.UNKNOWN) {

diff --git a/packages/gcf-utils/src/logging/gcf-logger.ts b/packages/gcf-utils/src/logging/gcf-logger.ts
@@ -15,92 +15,169 @@
 import pino from 'pino';
 import SonicBoom from 'sonic-boom';
 
-interface LogFn {
-  // eslint-disable-next-line @typescript-eslint/no-explicit-any
-  (msg: string, ...args: any[]): void;
-  // eslint-disable-next-line @typescript-eslint/no-explicit-any
-  (obj: object, msg?: string, ...args: any[]): void;
-}
+type Destination = NodeJS.WritableStream | SonicBoom;
 
 /**
  * A logger standardized logger for Google Cloud Functions
  */
-export interface GCFLogger {
+export class GCFLogger {
+  private destination!: Destination;
+  private pino!: pino.Logger;
+
+  constructor(customDestination?: Destination) {
+    this.initPinoLogger(customDestination);
+  }
+
+  /* eslint-disable @typescript-eslint/no-explicit-any */
+
   /**
    * Log at the trace level
    */
-  trace: LogFn;
+  public trace(msg: string, ...args: any[]): void;
+  public trace(obj: object, msg?: string, ...args: any[]): void;
+  public trace(
+    objOrMsg: object | string,
+    addMsg?: string,
+    ...args: any[]
+  ): void {
+    this.log('trace', objOrMsg, addMsg, ...args);
+  }
 
   /**
    * Log at the debug level
    */
-  debug: LogFn;
+  public debug(msg: string, ...args: any[]): void;
+  public debug(obj: object, msg?: string, ...args: any[]): void;
+  public debug(
+    objOrMsg: object | string,
+    addMsg?: string,
+    ...args: any[]
+  ): void {
+    this.log('debug', objOrMsg, addMsg, ...args);
+  }
 
   /**
    * Log at the info level
    */
-  info: LogFn;
+  public info(msg: string, ...args: any[]): void;
+  public info(obj: object, msg?: string, ...args: any[]): void;
+  public info(
+    objOrMsg: object | string,
+    addMsg?: string,
+    ...args: any[]
+  ): void {
+    this.log('info', objOrMsg, addMsg, ...args);
+  }
 
   /**
    * Log at the warn level
    */
-  warn: LogFn;
+  public warn(msg: string, ...args: any[]): void;
+  public warn(obj: object, msg?: string, ...args: any[]): void;
+  public warn(
+    objOrMsg: object | string,
+    addMsg?: string,
+    ...args: any[]
+  ): void {
+    this.log('warn', objOrMsg, addMsg, ...args);
+  }
 
   /**
    * Log at the error level
    */
-  error: LogFn;
+  public error(msg: string, ...args: any[]): void;
+  public error(obj: object, msg?: string, ...args: any[]): void;
+  public error(
+    objOrMsg: object | string,
+    addMsg?: string,
+    ...args: any[]
+  ): void {
+    this.log('error', objOrMsg, addMsg, ...args);
+  }
 
   /**
    * Log at the metric level
    */
-  metric: LogFn;
+  public metric(msg: string, ...args: any[]): void;
+  public metric(obj: object, msg?: string, ...args: any[]): void;
+  public metric(
+    objOrMsg: object | string,
+    addMsg?: string,
+    ...args: any[]
+  ): void {
+    this.log('metric', objOrMsg, addMsg, ...args);
+  }
+
+  private log(
+    level: string,
+    objOrMsg: object | string,
+    addMsg?: string,
+    ...args: any[]
+  ): void {
+    if (typeof objOrMsg === 'object') {
+      this.pino[level](objOrMsg, addMsg, ...args);
+    } else {
+      this.pino[level](objOrMsg, ...args);
+    }
+  }
+
+  /* eslint-enable @typescript-eslint/no-explicit-any */
 
   /**
    * Synchronously flush the buffer for this logger.
    * NOTE: Only supported for SonicBoom destinations
    */
-  flushSync: {(): void};
-}
+  public flushSync() {
+    if (this.destination instanceof SonicBoom) {
+      this.destination.flushSync();
+    }
+  }
 
-export function initLogger(
-  dest?: NodeJS.WritableStream | SonicBoom
-): GCFLogger {
-  const DEFAULT_LOG_LEVEL = 'trace';
-  const defaultOptions: pino.LoggerOptions = {
-    formatters: {
-      level: pinoLevelToCloudLoggingSeverity,
-    },
-    customLevels: {
-      metric: 30,
-    },
-    base: null,
-    messageKey: 'message',
-    timestamp: false,
-    level: DEFAULT_LOG_LEVEL,
-  };
+  /**
+   * Adds static properties to all logs
+   * @param properties static properties to bind
+   */
+  public addBindings(properties: object) {
+    this.pino = this.pino.child(properties);
+  }
 
-  dest = dest || pino.destination({sync: true});
-  const logger = pino(defaultOptions, dest);
-  Object.keys(logger).map(prop => {
-    if (logger[prop] instanceof Function) {
-      logger[prop] = logger[prop].bind(logger);
-    }
-  });
+  /**
+   * Return the current bindings
+   */
+  public getBindings(): object {
+    return this.pino.bindings();
+  }
 
-  const flushSync = () => {
-    // flushSync is only available for SonicBoom,
-    // which is the default destination wrapper for GCFLogger
-    if (dest instanceof SonicBoom) {
-      dest.flushSync();
-    }
-  };
+  /**
+   * Remove all current property bindings
+   */
+  public resetBindings() {
+    // Pino provides no way to remove bindings
+    // so we have to throw away the old logger
+    console.log('resetting');
+    this.initPinoLogger(this.destination);
+  }
 
-  return {
-    ...logger,
-    metric: logger.metric.bind(logger),
-    flushSync: flushSync,
-  };
+  private initPinoLogger(dest?: Destination) {
+    const defaultOptions = this.getPinoConfig();
+    this.destination = dest || pino.destination({sync: true});
+    this.pino = pino(defaultOptions, this.destination);
+  }
+
+  private getPinoConfig(): pino.LoggerOptions {
+    return {
+      formatters: {
+        level: pinoLevelToCloudLoggingSeverity,
+      },
+      customLevels: {
+        metric: 30,
+      },
+      base: null,
+      messageKey: 'message',
+      timestamp: false,
+      level: 'trace',
+    };
+  }
 }
 
 /**

diff --git a/packages/gcf-utils/src/logging/trigger-info-builder.ts b/packages/gcf-utils/src/logging/trigger-info-builder.ts
@@ -19,7 +19,6 @@ import crypto from 'crypto';
  * Information on GCF execution trigger
  */
 interface TriggerInfo {
-  message: string;
   trigger: {
     trigger_type: TriggerType;
     trigger_sender?: string;
@@ -59,7 +58,6 @@ export function buildTriggerInfo(
   const UNKNOWN = 'UNKNOWN';
 
   const triggerInfo: TriggerInfo = {
-    message: `Execution started by ${triggerType}`,
     trigger: {
       trigger_type: triggerType,
     },

diff --git a/packages/gcf-utils/test/gcf-bootstrapper.ts b/packages/gcf-utils/test/gcf-bootstrapper.ts
@@ -12,7 +12,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-import {GCFBootstrapper, WrapOptions} from '../src/gcf-utils';
+import {GCFBootstrapper, WrapOptions, logger} from '../src/gcf-utils';
 import {describe, beforeEach, afterEach, it} from 'mocha';
 import {GitHubAPI} from 'probot/lib/github';
 import {Options} from 'probot';
@@ -206,6 +206,46 @@ describe('GCFBootstrapper', () => {
 
       sinon.assert.calledOnce(enqueueTask);
     });
+
+    it('binds the trigger information to the logger', async () => {
+      await mockBootstrapper();
+      req.body = {
+        installation: {id: 1},
+      };
+      req.headers = {};
+      req.headers['x-github-event'] = 'issues';
+      req.headers['x-github-delivery'] = '123';
+      req.headers['x-cloudtasks-taskname'] = 'my-task';
+
+      await handler(req, response);
+
+      const expectedBindings = {
+        trigger: {trigger_type: 'Cloud Task', github_delivery_guid: '123'},
+      };
+      assert.deepEqual(logger.getBindings(), expectedBindings);
+    });
+
+    it('resets the logger on each call', async () => {
+      req.body = {
+        installation: {id: 1},
+      };
+      req.headers = {};
+      req.headers['x-github-event'] = 'issues';
+      req.headers['x-github-delivery'] = '123';
+      req.headers['x-cloudtasks-taskname'] = 'my-task';
+
+      const expectedBindings = {
+        trigger: {trigger_type: 'Cloud Task', github_delivery_guid: '123'},
+      };
+
+      await mockBootstrapper();
+
+      await handler(req, response);
+      assert.deepEqual(logger.getBindings(), expectedBindings);
+
+      await handler(req, response);
+      assert.deepEqual(logger.getBindings(), expectedBindings);
+    });
   });
 
   describe('loadProbot', () => {

diff --git a/packages/gcf-utils/test/gcf-logger.ts b/packages/gcf-utils/test/gcf-logger.ts
@@ -13,7 +13,7 @@
 // limitations under the License.
 
 import {logger} from '../src/gcf-utils';
-import {GCFLogger, initLogger} from '../src/logging/gcf-logger';
+import {GCFLogger} from '../src/logging/gcf-logger';
 import {describe, beforeEach, it} from 'mocha';
 import {ObjectWritableMock} from 'stream-mock';
 import {validateLogs, LogLine, logLevels} from './test-helpers';
@@ -62,7 +62,9 @@ describe('GCFLogger', () => {
 
     beforeEach(() => {
       destination = new ObjectWritableMock();
-      logger = initLogger(destination) as GCFLogger & {[key: string]: Function};
+      logger = new GCFLogger(destination) as GCFLogger & {
+        [key: string]: Function;
+      };
     });
 
     testAllLevels();

diff --git a/packages/gcf-utils/test/integration/gcf-logger-integration.ts b/packages/gcf-utils/test/integration/gcf-logger-integration.ts
@@ -12,7 +12,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-import {GCFLogger, initLogger} from '../../src/logging/gcf-logger';
+import {GCFLogger} from '../../src/logging/gcf-logger';
 import {describe, beforeEach, afterEach, it} from 'mocha';
 import pino from 'pino';
 import {validateLogs, LogLine, logLevels} from '../test-helpers';
@@ -69,7 +69,9 @@ describe('GCFLogger Integration', () => {
 
   beforeEach(() => {
     destination = pino.destination(testStreamPath);
-    logger = initLogger(destination) as GCFLogger & {[key: string]: Function};
+    logger = new GCFLogger(destination) as GCFLogger & {
+      [key: string]: Function;
+    };
   });
 
   testAllLevels();