diff --git a/package.json b/package.json index 2c4f185a..39ce01bb 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 .", @@ -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/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..318858e5 --- /dev/null +++ b/src/middleware/express.ts @@ -0,0 +1,80 @@ +/*! + * 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 {HttpRequest, middleware as commonMiddleware} from '@google-cloud/logging'; +import {GCPEnv} from 'google-auth-library'; +import * as winston from 'winston'; + +import {LOGGING_TRACE_KEY} from '../common'; +import {LoggingWinston} from '../index'; +import * as types from '../types/core'; + +import {makeChildLogger} from './make-child-logger'; + +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.common.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..7783d982 --- /dev/null +++ b/test/middleware/express.ts @@ -0,0 +1,132 @@ +/*! + * 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 {GCPEnv} from 'google-auth-library'; +import {LogEntry} from 'winston'; +import * as TransportStream from 'winston-transport'; + +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; + }, + async getEnv() { + return authEnvironment; + } + } + } + } + }; + } + + 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); + }); +});