feat(gcf-utils): add trigger info as bindings to all log statements (#…

…796)

* feat(gcf-utils): add trigger info as bindings to all log statements

* don't recreate logger to attach bindings

* move deletion of message prop to main gcf method

* move trigger message addition to gcf-bootstrapper

* remove extra trigger info logging

Co-authored-by: Jeff Ching <chingor@google.com>

packages/gcf-utils/src/gcf-utils.ts

@@ -54,7 +54,7 @@ export interface WrapOptions {
   logging: boolean;
 }
 
-export const logger: GCFLogger = initLogger();
+export let logger: GCFLogger = initLogger();
 
 export interface CronPayload {
   repository: {
@@ -181,6 +181,19 @@ export class GCFBootstrapper {
     return TriggerType.UNKNOWN;
   }
 
+  /**
+   * Binds the given properties to the logger so that every logged statement
+   * includes these properties.
+   *
+   * NOTE: statements logged before this method is called will not include
+   * this information
+   *
+   * @param bindings object containing properties to bind to the logger
+   */
+  private static bindPropertiesToLogger(bindings: {}) {
+    logger = logger.child(bindings);
+  }
+
   gcf(
     appFn: ApplicationFunction,
     wrapOptions?: WrapOptions
@@ -200,7 +213,9 @@ export class GCFBootstrapper {
         taskId
       );
 
-      logger.metric(buildTriggerInfo(triggerType, id, request.body));
+      const triggerInfo = buildTriggerInfo(triggerType, id, request.body);
+      GCFBootstrapper.bindPropertiesToLogger(triggerInfo);
+      logger.metric(`Execution started by ${triggerType}`);
 
       try {
         if (triggerType === TriggerType.UNKNOWN) {

packages/gcf-utils/src/logging/gcf-logger.ts

@@ -22,22 +22,86 @@ interface LogFn {
   (obj: object, msg?: string, ...args: any[]): void;
 }
 
+interface Bindings {
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  [key: string]: any;
+}
+
 /**
  * A logger standardized logger for Google Cloud Functions
  */
 export interface GCFLogger {
+  /**
+   * Log at the trace level
+   */
   trace: LogFn;
+
+  /**
+   * Log at the debug level
+   */
   debug: LogFn;
+
+  /**
+   * Log at the info level
+   */
   info: LogFn;
+
+  /**
+   * Log at the warn level
+   */
   warn: LogFn;
+
+  /**
+   * Log at the error level
+   */
   error: LogFn;
+
+  /**
+   * Log at the metric level
+   */
   metric: LogFn;
+
+  /**
+   * Create a child logger
+   * @param bindings static properties that will be included
+   * in all statements logged from the child logger
+   */
+  child: {(bindings: Bindings): GCFLogger};
+
+  /**
+   * Get the bindings associated with this logger
+   */
+  bindings: {(): Bindings};
+
+  /**
+   * Synchronously flush the buffer for this logger.
+   * NOTE: Only supported for SonicBoom destinations
+   */
   flushSync: {(): void};
 }
 
-export function initLogger(
-  dest?: NodeJS.WritableStream | SonicBoom
-): GCFLogger {
+/**
+ * GCFLogger customization options
+ */
+export interface GCFLoggerOptions {
+  /**
+   * An alternate destination to write logs.
+   * Default is stdout wrapped in SonicBoom
+   */
+  destination?: NodeJS.WritableStream | SonicBoom;
+
+  /**
+   * static properties that will be included
+   * in all statements logged
+   */
+  bindings?: Bindings;
+}
+
+/**
+ * Initialize a GCFLogger instance
+ * @param options options for instance initialization
+ */
+export function initLogger(options?: GCFLoggerOptions): GCFLogger {
   const DEFAULT_LOG_LEVEL = 'trace';
   const defaultOptions: pino.LoggerOptions = {
     formatters: {
@@ -52,26 +116,58 @@ export function initLogger(
     level: DEFAULT_LOG_LEVEL,
   };
 
-  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);
-    }
-  });
+  const destination = options?.destination || pino.destination({sync: true});
+  let logger = pino(defaultOptions, destination);
+
+  if (options?.bindings) {
+    logger = logger.child(options.bindings);
+  }
+
+  bindPinoFunctions(logger);
 
   const flushSync = () => {
     // flushSync is only available for SonicBoom,
     // which is the default destination wrapper for GCFLogger
-    if (dest instanceof SonicBoom) {
-      dest.flushSync();
+    if (destination instanceof SonicBoom) {
+      destination.flushSync();
     }
   };
 
+  return pinoToGCFLogger(logger, flushSync);
+}
+
+/**
+ * Binds the given logger instance to Pino logger functions
+ * @param logger instance to bind
+ */
+function bindPinoFunctions(logger: pino.Logger): pino.Logger {
+  Object.keys(logger).map(prop => {
+    if (logger[prop] instanceof Function) {
+      logger[prop] = logger[prop].bind(logger);
+    }
+  });
+  return logger;
+}
+
+/**
+ * Converts a Pino logger instance to a GCFLogger instance
+ * @param pinoLogger pino logger to convert
+ * @param flushSync the flushSync function to apply to the returned GCFLogger
+ */
+function pinoToGCFLogger(
+  pinoLogger: pino.Logger,
+  flushSync: {(): void}
+): GCFLogger {
   return {
-    ...logger,
-    metric: logger.metric.bind(logger),
+    ...pinoLogger,
+    metric: pinoLogger.metric.bind(pinoLogger),
     flushSync: flushSync,
+    bindings: pinoLogger.bindings,
+    child: (bindings: Bindings) => {
+      const child = pinoLogger.child(bindings);
+      bindPinoFunctions(child);
+      return pinoToGCFLogger(child, flushSync);
+    },
   };
 }
 

packages/gcf-utils/src/logging/trigger-info-builder.ts

@@ -18,7 +18,7 @@ import crypto from 'crypto';
 /**
  * Information on GCF execution trigger
  */
-interface TriggerInfo {
+export interface TriggerInfo {
   trigger: {
     trigger_type: TriggerType;
     trigger_sender?: string;
@@ -37,7 +37,6 @@ interface TriggerInfo {
       repo_name: string;
       url: string;
     };
-    message: string;
   };
 }
 
@@ -58,7 +57,6 @@ export function buildTriggerInfo(
   const triggerInfo: TriggerInfo = {
     trigger: {
       trigger_type: triggerType,
-      message: `Execution started by ${triggerType}`,
     },
   };
 

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';
@@ -367,4 +367,26 @@ describe('GCFBootstrapper', () => {
       assert.strictEqual(latest, 'projects/foo/secrets/bar');
     });
   });
+
+  describe('bindPropertiesToLogger', () => {
+    it('binds given properties', () => {
+      const triggerInfoWithoutMessage = {
+        trigger: {
+          trigger_type: 'GITHUB_WEBHOOK',
+          trigger_sender: 'some sender',
+          payload_hash: '123456',
+
+          trigger_source_repo: {
+            owner: 'foo owner',
+            owner_type: 'Org',
+            repo_name: 'bar name',
+            url: 'some url',
+          },
+        },
+      };
+
+      GCFBootstrapper['bindPropertiesToLogger'](triggerInfoWithoutMessage);
+      assert.deepEqual(logger.bindings(), triggerInfoWithoutMessage);
+    });
+  });
 });

packages/gcf-utils/test/gcf-logger.ts

@@ -26,7 +26,9 @@ describe('GCFLogger', () => {
   });
   describe('logger instance', () => {
     let destination: ObjectWritableMock;
-    let logger: GCFLogger & {[key: string]: Function};
+    let loggerNoBindings: GCFLogger & {[key: string]: Function};
+    let loggerWithBindings: GCFLogger & {[key: string]: Function};
+    const bindings = {foo: 'bar-binding'};
 
     function readLogsAsObjects(writeStream: ObjectWritableMock): LogLine[] {
       try {
@@ -41,13 +43,13 @@ describe('GCFLogger', () => {
     function testAllLevels() {
       for (const level of Object.keys(logLevels)) {
         it(`logs ${level} level string`, () => {
-          logger[level]('hello world');
+          loggerNoBindings[level]('hello world');
           const loggedLines: LogLine[] = readLogsAsObjects(destination);
           validateLogs(loggedLines, 1, ['hello world'], [], logLevels[level]);
         });
 
         it(`logs ${level} level json`, () => {
-          logger[level]({hello: 'world'});
+          loggerNoBindings[level]({hello: 'world'});
           const loggedLines: LogLine[] = readLogsAsObjects(destination);
           validateLogs(
             loggedLines,
@@ -57,12 +59,41 @@ describe('GCFLogger', () => {
             logLevels[level]
           );
         });
+
+        it(`logs ${level} level string with bindings`, () => {
+          loggerWithBindings[level]('hello world');
+          const loggedLines: LogLine[] = readLogsAsObjects(destination);
+          validateLogs(
+            loggedLines,
+            1,
+            ['hello world'],
+            [bindings],
+            logLevels[level]
+          );
+        });
+
+        it(`logs ${level} level json with bindings`, () => {
+          loggerWithBindings[level]({hello: 'world'});
+          const loggedLines: LogLine[] = readLogsAsObjects(destination);
+          validateLogs(
+            loggedLines,
+            1,
+            [],
+            [{...bindings, hello: 'world'}],
+            logLevels[level]
+          );
+        });
       }
     }
 
     beforeEach(() => {
       destination = new ObjectWritableMock();
-      logger = initLogger(destination) as GCFLogger & {[key: string]: Function};
+      loggerNoBindings = initLogger({destination}) as GCFLogger & {
+        [key: string]: Function;
+      };
+      loggerWithBindings = loggerNoBindings.child(bindings) as GCFLogger & {
+        [key: string]: Function;
+      };
     });
 
     testAllLevels();