From dcdd281b06524203788946470fbb8012179d2c98 Mon Sep 17 00:00:00 2001 From: Aziz Sonawalla <35513492+azizsonawalla@users.noreply.github.com> Date: Wed, 2 Sep 2020 11:34:00 -0400 Subject: [PATCH] feat: bind trigger information to all logs (#926) --- packages/gcf-utils/src/gcf-utils.ts | 12 +- packages/gcf-utils/src/logging/gcf-logger.ts | 177 +++++++++++++----- .../src/logging/trigger-info-builder.ts | 2 - packages/gcf-utils/test/gcf-bootstrapper.ts | 42 ++++- packages/gcf-utils/test/gcf-logger.ts | 6 +- .../integration/gcf-logger-integration.ts | 6 +- .../gcf-utils/test/trigger-info-builder.ts | 11 -- 7 files changed, 185 insertions(+), 71 deletions(-) diff --git a/packages/gcf-utils/src/gcf-utils.ts b/packages/gcf-utils/src/gcf-utils.ts index 5a0ee6cab75..f01b9ac8028 100644 --- 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 index c5edb03f341..3f30ed6c62e 100644 --- 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 index 51be076f6fc..dd5575b8529 100644 --- 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 index cdf233b33eb..fb7158f328a 100644 --- 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 index 2117c986e49..f7a00e67fcf 100644 --- 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 index e53401d48c7..b9c9e21f309 100644 --- 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(); diff --git a/packages/gcf-utils/test/trigger-info-builder.ts b/packages/gcf-utils/test/trigger-info-builder.ts index efabd890a24..0950edbccfe 100644 --- a/packages/gcf-utils/test/trigger-info-builder.ts +++ b/packages/gcf-utils/test/trigger-info-builder.ts @@ -23,7 +23,6 @@ describe('buildTriggerInfo', () => { const triggerType = TriggerType.PUBSUB; const triggerInfo = buildTriggerInfo(triggerType, '', '', requestBody); const expectedInfo = { - message: 'Execution started by Pub/Sub', trigger: { trigger_type: 'Pub/Sub', }, @@ -36,7 +35,6 @@ describe('buildTriggerInfo', () => { const triggerType = TriggerType.SCHEDULER; const triggerInfo = buildTriggerInfo(triggerType, '', '', requestBody); const expectedInfo = { - message: 'Execution started by Cloud Scheduler', trigger: { trigger_type: 'Cloud Scheduler', }, @@ -49,7 +47,6 @@ describe('buildTriggerInfo', () => { const triggerType = TriggerType.TASK; const triggerInfo = buildTriggerInfo(triggerType, '1234', '', requestBody); const expectedInfo = { - message: 'Execution started by Cloud Task', trigger: { trigger_type: 'Cloud Task', github_delivery_guid: '1234', @@ -69,7 +66,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'testUser', @@ -98,7 +94,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'testUser', @@ -127,7 +122,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'testUser', @@ -156,7 +150,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'testUser', @@ -185,7 +178,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'testUser', @@ -214,7 +206,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'testUser', @@ -243,7 +234,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'testUser', @@ -272,7 +262,6 @@ describe('buildTriggerInfo', () => { requestBody ); const expectedInfo = { - message: 'Execution started by GitHub Webhook', trigger: { trigger_type: 'GitHub Webhook', trigger_sender: 'UNKNOWN',