From 9453a2d2cdba1aa4823cab620d2e702a61d993b8 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Fri, 28 Sep 2018 14:55:00 -0700 Subject: [PATCH 1/2] feature: request logging middleware for express --- package.json | 2 +- src/common.ts | 2 +- src/middleware/express.ts | 79 ++++++++++++++++ src/middleware/make-child-logger.ts | 31 +++++++ test/middleware/express.ts | 130 +++++++++++++++++++++++++++ test/middleware/make-child-logger.ts | 71 +++++++++++++++ 6 files changed, 313 insertions(+), 2 deletions(-) create mode 100644 src/middleware/express.ts create mode 100644 src/middleware/make-child-logger.ts create mode 100644 test/middleware/express.ts create mode 100644 test/middleware/make-child-logger.ts diff --git a/package.json b/package.json index 2c4f185a..0e685150 100644 --- a/package.json +++ b/package.json @@ -39,7 +39,7 @@ "samples-test": "cd samples/ && npm link ../ && npm test && cd ../", "presystem-test": "npm run pretest", "system-test": "mocha build/system-test --timeout 600000", - "test": "nyc mocha build/test", + "test": "nyc mocha --recursive build/test", "check": "gts check", "clean": "gts clean", "compile": "tsc -p .", diff --git a/src/common.ts b/src/common.ts index e0f3fc60..6fa169d4 100644 --- a/src/common.ts +++ b/src/common.ts @@ -77,7 +77,7 @@ function getCurrentTraceFromAgent(): string|null { export class LoggingCommon { private inspectMetadata: boolean; private levels: {[name: string]: number}; - private stackdriverLog: + stackdriverLog: types.StackdriverLog; // TODO: add type for @google-cloud/logging private resource: types.MonitoredResource|undefined; private serviceContext: types.ServiceContext|undefined; diff --git a/src/middleware/express.ts b/src/middleware/express.ts new file mode 100644 index 00000000..83c6af66 --- /dev/null +++ b/src/middleware/express.ts @@ -0,0 +1,79 @@ +/*! + * Copyright 2018 Google LLC + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import * as winston from 'winston'; +import {middleware as commonMiddleware, HttpRequest} from '@google-cloud/logging'; +import {LoggingWinston} from '../index'; +import * as types from '../types/core'; + +import {makeChildLogger} from './make-child-logger'; +import { GCPEnv } from 'google-auth-library'; +import { LOGGING_TRACE_KEY } from '../common'; + +export const APP_LOG_SUFFIX = 'applog'; + +export interface MiddlewareOptions extends types.Options { + level?: string; + levels?: winston.config.AbstractConfigSetLevels; +} + +export async function middleware(options?: MiddlewareOptions) { + const defaultOptions = { + logName: 'winston_log', + level: 'info', + levels: winston.config.npm.levels + }; + options = Object.assign({}, defaultOptions, options); + + const loggingWinstonApp = new LoggingWinston({ + ...options, + logName: `${options.logName}_${APP_LOG_SUFFIX}` + }); + const logger = winston.createLogger({ + level: options.level, + levels: options.levels, + transports: [loggingWinstonApp] + }); + + const auth = loggingWinstonApp.stackdriverLog.logging.auth; + const [env, projectId] = + await Promise.all([auth.getEnv(), auth.getProjectId()]); + + // Unless we are running on Google App Engine or Cloud Functions, generate a + // parent request log entry that all the request specific logs ("app logs") + // will nest under. GAE and GCF generate the parent request logs + // automatically. + let emitRequestLog; + if (env !== GCPEnv.APP_ENGINE && env !== GCPEnv.CLOUD_FUNCTIONS) { + const loggingWinstonReq = new LoggingWinston(options); + const requestLogger = winston.createLogger({ + level: options.level, + levels: options.levels, + transports: [loggingWinstonReq] + }); + emitRequestLog = (httpRequest: HttpRequest, trace: string) => { + requestLogger.info({[LOGGING_TRACE_KEY]: trace, httpRequest}); + }; + } + + return { + logger, + mw: commonMiddleware.express.makeMiddleware( + projectId, (trace: string) => { + return makeChildLogger(logger, trace); + }, emitRequestLog) + }; +} diff --git a/src/middleware/make-child-logger.ts b/src/middleware/make-child-logger.ts new file mode 100644 index 00000000..d71c188f --- /dev/null +++ b/src/middleware/make-child-logger.ts @@ -0,0 +1,31 @@ +/*! + * Copyright 2018 Google LLC + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import * as winston from 'winston'; +import {LOGGING_TRACE_KEY} from '../index'; + +// TODO: winston2 support. +export function makeChildLogger(logger: winston.Logger, trace: string) { + const childLogger = Object.create(logger, { + write: { + value(info: winston.LogEntry) { + info[LOGGING_TRACE_KEY] = trace; + return logger.write(info); + } + } + }); + return childLogger; +} diff --git a/test/middleware/express.ts b/test/middleware/express.ts new file mode 100644 index 00000000..4009a2f9 --- /dev/null +++ b/test/middleware/express.ts @@ -0,0 +1,130 @@ +/*! + * Copyright 2018 Google LLC + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import * as assert from 'assert'; +import {LogEntry} from 'winston'; +import * as TransportStream from 'winston-transport'; +import {GCPEnv} from 'google-auth-library'; + +const inject = require('require-inject'); + +// types-only import. Actual require is done through require-inject below. +import {MiddlewareOptions} from '../../src/middleware/express'; + +const FAKE_PROJECT_ID = 'project-🦄'; +const FAKE_GENERATED_MIDDLEWARE = () => {}; +const FAKE_ENVIRONMENT = 'FAKE_ENVIRONMENT'; + +let authEnvironment: string; +let passedOptions: Array; +let loggedEntry: LogEntry; + +class FakeLoggingWinston extends TransportStream { + // tslint:disable-next-line:no-any Doing "just enough" faking. + common: any; + + constructor(options: MiddlewareOptions) { + super(options); + passedOptions.push(options); + this.common = { + stackdriverLog: { + logging: { + auth: { + async getProjectId() { + return FAKE_PROJECT_ID; + } + } + } + } + }; + } + + log(info: LogEntry, cb: Function) { + loggedEntry = info; + cb(); + } +} + +let passedProjectId: string|undefined; +let passedEmitRequestLog: Function|undefined; +function fakeMakeMiddleware( + projectId: string, makeChildLogger: Function, + emitRequestLog: Function): Function { + passedProjectId = projectId; + passedEmitRequestLog = emitRequestLog; + return FAKE_GENERATED_MIDDLEWARE; +} + +const {middleware, APP_LOG_SUFFIX} = inject('../../src/middleware/express', { + '../../src/index': {LoggingWinston: FakeLoggingWinston}, + '@google-cloud/logging': + {middleware: {express: {makeMiddleware: fakeMakeMiddleware}}} +}); + +describe('middleware/express', () => { + beforeEach(() => { + passedOptions = []; + passedProjectId = undefined; + passedEmitRequestLog = undefined; + authEnvironment = FAKE_ENVIRONMENT; + }); + + it('should create and return a middleware', async () => { + const {mw} = await middleware(); + assert.strictEqual(mw, FAKE_GENERATED_MIDDLEWARE); + }); + + it('should generate two loggers with default logName and level', async () => { + await middleware(); + // Should generate two loggers with the expected names. + assert.ok(passedOptions); + assert.strictEqual(passedOptions.length, 2); + assert.ok(passedOptions.some( + option => option!.logName === `winston_log_${APP_LOG_SUFFIX}`)); + assert.ok(passedOptions.some(option => option!.logName === `winston_log`)); + assert.ok(passedOptions.every(option => option!.level === 'info')); + }); + + it('should prefer user-provided logName and level', async () => { + const LOGNAME = '㏒'; + const LEVEL = 'fatal'; + const OPTIONS = {logName: LOGNAME, level: LEVEL}; + await middleware(OPTIONS); + assert.ok(passedOptions); + assert.strictEqual(passedOptions.length, 2); + assert.ok(passedOptions.some( + option => option!.logName === `${LOGNAME}_${APP_LOG_SUFFIX}`)); + assert.ok(passedOptions.some(option => option!.logName === LOGNAME)); + assert.ok(passedOptions.every(option => option!.level === LEVEL)); + }); + + it('should acquire the projectId and pass to makeMiddleware', async () => { + await middleware(); + assert.strictEqual(passedProjectId, FAKE_PROJECT_ID); + }); + + [GCPEnv.APP_ENGINE, GCPEnv.CLOUD_FUNCTIONS].forEach( + env => { + it(`should not generate the request logger on ${env}`, async () => { + authEnvironment = env; + await middleware(); + assert.ok(passedOptions); + assert.strictEqual(passedOptions.length, 1); + // emitRequestLog parameter to makeChildLogger should be undefined. + assert.strictEqual(passedEmitRequestLog, undefined); + }); + }); +}); diff --git a/test/middleware/make-child-logger.ts b/test/middleware/make-child-logger.ts new file mode 100644 index 00000000..87a43a78 --- /dev/null +++ b/test/middleware/make-child-logger.ts @@ -0,0 +1,71 @@ +import * as assert from 'assert'; +import * as winston from 'winston'; +import {LOGGING_TRACE_KEY} from '../../src/common'; + +import {makeChildLogger} from '../../src/middleware/make-child-logger'; + +describe('makeChildLogger', () => { + const FAKE_TRACE = '🤥'; + const LOGGER = winston.createLogger( + {transports: [new winston.transports.Console({silent: true})]}); + const origWrite = LOGGER.write; + + afterEach(() => { + LOGGER.write = origWrite; + }); + + it('should return a winston-like logger', () => { + const child = makeChildLogger(LOGGER, FAKE_TRACE); + let logEntry: winston.LogEntry; + // tslint:disable-next-line:no-any + (LOGGER.write as any) = (logEntry_: winston.LogEntry) => { + logEntry = logEntry_; + }; + + child.info('hello'); + assert.strictEqual(logEntry!.message, 'hello'); + assert.strictEqual(logEntry!.level, 'info'); + + child.error('👾', {key: '🎃'}); + assert.strictEqual(logEntry!.message, '👾'); + assert.strictEqual(logEntry!.level, 'error'); + assert.strictEqual(logEntry!.key, '🎃'); + + child.warn('hello %d', 56, {key: 'value'}); + assert.strictEqual(logEntry!.message, 'hello %d'); + assert.strictEqual(logEntry!.level, 'warn'); + assert.strictEqual(logEntry!.key, undefined); + + child.log('silly', '🎈'); + assert.strictEqual(logEntry!.message, '🎈'); + assert.strictEqual(logEntry!.level, 'silly'); + }); + + it('should override only the write function', () => { + const child = makeChildLogger(LOGGER, FAKE_TRACE); + assert.strictEqual(child.warn, LOGGER.warn); + assert.notStrictEqual(child.write, LOGGER.write); + }); + + it('should inject the LOGGING_TRACE_KEY into the metadata', () => { + const child = makeChildLogger(LOGGER, FAKE_TRACE); + let trace; + // tslint:disable-next-line:no-any + (LOGGER.write as any) = (info: winston.LogEntry) => { + trace = info[LOGGING_TRACE_KEY]; + }; + child.debug('hello world'); + assert.strictEqual(trace, FAKE_TRACE); + }); + + it('should overwrite existing LOGGING_TRACE_KEY value', () => { + const child = makeChildLogger(LOGGER, FAKE_TRACE); + let trace; + // tslint:disable-next-line:no-any + (LOGGER.write as any) = (info: winston.LogEntry) => { + trace = info[LOGGING_TRACE_KEY]; + }; + child.debug('hello world', {[LOGGING_TRACE_KEY]: 'to-be-clobbered'}); + assert.strictEqual(trace, FAKE_TRACE); + }); +}); From f386df33967a410675f130e19628c82526311422 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Tue, 12 Feb 2019 12:07:38 -0800 Subject: [PATCH 2/2] make tests pass --- package.json | 2 +- src/middleware/express.ts | 23 ++++++++++++----------- test/middleware/express.ts | 28 +++++++++++++++------------- 3 files changed, 28 insertions(+), 25 deletions(-) diff --git a/package.json b/package.json index 0e685150..39ce01bb 100644 --- a/package.json +++ b/package.json @@ -52,7 +52,7 @@ "predocs-test": "npm run docs" }, "dependencies": { - "@google-cloud/logging": "^4.0.1", + "@google-cloud/logging": "^4.4.0", "lodash.mapvalues": "^4.6.0", "logform": "^2.0.0", "semver": "^5.5.1", diff --git a/src/middleware/express.ts b/src/middleware/express.ts index 83c6af66..318858e5 100644 --- a/src/middleware/express.ts +++ b/src/middleware/express.ts @@ -14,14 +14,15 @@ * limitations under the License. */ +import {HttpRequest, middleware as commonMiddleware} from '@google-cloud/logging'; +import {GCPEnv} from 'google-auth-library'; import * as winston from 'winston'; -import {middleware as commonMiddleware, HttpRequest} from '@google-cloud/logging'; + +import {LOGGING_TRACE_KEY} from '../common'; import {LoggingWinston} from '../index'; import * as types from '../types/core'; import {makeChildLogger} from './make-child-logger'; -import { GCPEnv } from 'google-auth-library'; -import { LOGGING_TRACE_KEY } from '../common'; export const APP_LOG_SUFFIX = 'applog'; @@ -38,17 +39,15 @@ export async function middleware(options?: MiddlewareOptions) { }; options = Object.assign({}, defaultOptions, options); - const loggingWinstonApp = new LoggingWinston({ - ...options, - logName: `${options.logName}_${APP_LOG_SUFFIX}` - }); + const loggingWinstonApp = new LoggingWinston( + {...options, logName: `${options.logName}_${APP_LOG_SUFFIX}`}); const logger = winston.createLogger({ level: options.level, levels: options.levels, transports: [loggingWinstonApp] }); - const auth = loggingWinstonApp.stackdriverLog.logging.auth; + const auth = loggingWinstonApp.common.stackdriverLog.logging.auth; const [env, projectId] = await Promise.all([auth.getEnv(), auth.getProjectId()]); @@ -72,8 +71,10 @@ export async function middleware(options?: MiddlewareOptions) { return { logger, mw: commonMiddleware.express.makeMiddleware( - projectId, (trace: string) => { - return makeChildLogger(logger, trace); - }, emitRequestLog) + projectId, + (trace: string) => { + return makeChildLogger(logger, trace); + }, + emitRequestLog) }; } diff --git a/test/middleware/express.ts b/test/middleware/express.ts index 4009a2f9..7783d982 100644 --- a/test/middleware/express.ts +++ b/test/middleware/express.ts @@ -15,9 +15,9 @@ */ import * as assert from 'assert'; +import {GCPEnv} from 'google-auth-library'; import {LogEntry} from 'winston'; import * as TransportStream from 'winston-transport'; -import {GCPEnv} from 'google-auth-library'; const inject = require('require-inject'); @@ -45,6 +45,9 @@ class FakeLoggingWinston extends TransportStream { auth: { async getProjectId() { return FAKE_PROJECT_ID; + }, + async getEnv() { + return authEnvironment; } } } @@ -70,7 +73,7 @@ function fakeMakeMiddleware( const {middleware, APP_LOG_SUFFIX} = inject('../../src/middleware/express', { '../../src/index': {LoggingWinston: FakeLoggingWinston}, - '@google-cloud/logging': + '@google-cloud/logging': {middleware: {express: {makeMiddleware: fakeMakeMiddleware}}} }); @@ -116,15 +119,14 @@ describe('middleware/express', () => { assert.strictEqual(passedProjectId, FAKE_PROJECT_ID); }); - [GCPEnv.APP_ENGINE, GCPEnv.CLOUD_FUNCTIONS].forEach( - env => { - it(`should not generate the request logger on ${env}`, async () => { - authEnvironment = env; - await middleware(); - assert.ok(passedOptions); - assert.strictEqual(passedOptions.length, 1); - // emitRequestLog parameter to makeChildLogger should be undefined. - assert.strictEqual(passedEmitRequestLog, undefined); - }); - }); + [GCPEnv.APP_ENGINE, GCPEnv.CLOUD_FUNCTIONS].forEach(env => { + it(`should not generate the request logger on ${env}`, async () => { + authEnvironment = env; + await middleware(); + assert.ok(passedOptions); + assert.strictEqual(passedOptions.length, 1); + // emitRequestLog parameter to makeChildLogger should be undefined. + assert.strictEqual(passedEmitRequestLog, undefined); + }); + }); });