feature: request logging middleware for express

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",

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;

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)
+  };
+}

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;
+}

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<MiddlewareOptions|undefined>;
+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);
+    });
+  });
+});

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);
+  });
+});