refactor(middleware): use common code from logging

Start using refactored code from @g-c/logging.

package.json

@@ -60,7 +60,7 @@
     "presystem-test": "npm run compile",
     "samples-test": "cd samples/ && npm link ../ && npm test && cd ../",
     "system-test": "mocha build/system-test --timeout 600000",
-    "test": "nyc mocha build/test",
+    "test": "nyc mocha build/test build/test/middleware",
     "check": "gts check",
     "clean": "gts clean",
     "compile": "tsc -p .",
@@ -72,8 +72,7 @@
     "codecov": "nyc report --reporter=json && codecov -f .coverage/*.json"
   },
   "dependencies": {
-    "@google-cloud/logging": "^4.0.1",
-    "@opencensus/propagation-stackdriver": "^0.0.6"
+    "@google-cloud/logging": "^4.1.0"
   },
   "devDependencies": {
     "@google-cloud/nodejs-repo-tools": "^2.3.0",

src/middleware/express.ts

@@ -13,34 +13,25 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
-
-import * as context from '@opencensus/propagation-stackdriver';
+import {HttpRequest, middleware as commonMiddleware} from '@google-cloud/logging';
 import * as bunyan from 'bunyan';
-import * as http from 'http';
-
-export type Request = http.IncomingMessage;
-export type Response = http.ServerResponse;
-export type NextFunction = (err?: Error) => void;
 
 import {LOGGING_TRACE_KEY, LoggingBunyan} from '../index';
 import * as types from '../types/core';
 
+export const APP_LOG_SUFFIX = 'applog';
+
 // @types/bunyan doesn't export Logger. Access it via ReturnType on
 // createLogger.
-type Logger = ReturnType<typeof bunyan.createLogger>;
-
-export interface AnnotatedRequest extends Request {
-  log: Logger;
-}
+export type Logger = ReturnType<typeof bunyan.createLogger>;
 
 export interface MiddlewareOptions extends types.Options {
   level?: types.LogLevel;
 }
 
 export interface MiddlewareReturnType {
   logger: Logger;
-  // tslint:disable-next-line:no-any express middleware.
-  mw: (req: Request, res: Response, next: NextFunction) => any;
+  mw: ReturnType<typeof commonMiddleware.express.makeMiddleware>;
 }
 
 /**
@@ -51,41 +42,28 @@ export async function middleware(options?: MiddlewareOptions):
   const defaultOptions = {logName: 'bunyan_log', level: 'info'};
   options = Object.assign({}, defaultOptions, options);
 
-  const bunyan = require('bunyan');
-  const loggingBunyan = new LoggingBunyan(options);
-  const projectId =
-      await loggingBunyan.stackdriverLog.logging.auth.getProjectId();
-  // Failure to acquire projectId from auth would throw to the user.
+  // TODO: Create a http request logger unless we are running on GAE or GCF.
 
+  const loggingBunyanApp = new LoggingBunyan(Object.assign({}, options, {
+    // For request bundling to work, the parent (request) and child (app) logs
+    // need to have distinct names. For exact requirements see:
+    // https://cloud.google.com/appengine/articles/logging#linking_app_logs_and_requests
+    logName: `${options.logName}_${APP_LOG_SUFFIX}`
+  }));
   const logger = bunyan.createLogger({
-    name: options.logName,
-    streams: [loggingBunyan.stream(options.level as types.LogLevel)]
+    name: `${options.logName}_${APP_LOG_SUFFIX}`,
+    streams: [loggingBunyanApp.stream(options.level as types.LogLevel)]
   });
 
+  const projectId =
+      await loggingBunyanApp.stackdriverLog.logging.auth.getProjectId();
+
   return {
     logger,
-    mw: (req: Request, res: Response, next: NextFunction) => {
-      const wrapper = {
-        setHeader(name: string, value: string) {
-          req.headers[name] = value;
-        },
-        getHeader(name: string) {
-          return req.headers[name];
-        }
-      };
-
-      let spanContext = context.extract(wrapper);
-      if (!spanContext) {
-        // We were the first actor to detect lack of context. Establish context.
-        spanContext = context.generate();
-        context.inject(wrapper, spanContext);
-      }
-
-      const trace = `projects/${projectId}/traces/${spanContext.traceId}`;
-
-      (req as AnnotatedRequest).log =
-          logger.child({[LOGGING_TRACE_KEY]: trace}, true /*simple child */);
-      next();
-    }
+    mw: commonMiddleware.express.makeMiddleware(projectId, makeChildLogger)
   };
+
+  function makeChildLogger(trace: string) {
+    return logger.child({[LOGGING_TRACE_KEY]: trace}, true /* simple child */);
+  }
 }

system-test/test-middleware-express.ts

@@ -57,7 +57,7 @@ describe('express middleware', () => {
       const next = async () => {
         // At this point fakeRequest.log should have been installed.
         // tslint:disable-next-line:no-any
-        (fakeRequest as any as elb.AnnotatedRequest).log.info(LOG_MESSAGE);
+        (fakeRequest as any).log.info(LOG_MESSAGE);
 
         await delay(WRITE_CONSISTENCY_DELAY_MS);
 

test/middleware/test-express.ts

@@ -0,0 +1,96 @@
+/*!
+ * 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 * as proxyquire from 'proxyquire';
+
+// types-only import. Actual require is done through proxyquire below.
+import {MiddlewareOptions} from '../../src/middleware/express';
+
+const FAKE_PROJECT_ID = 'project-🦄';
+const FAKE_GENERATED_MIDDLEWARE = () => {};
+
+let passedOptions: MiddlewareOptions|undefined;
+
+class FakeLoggingBunyan {
+  // tslint:disable-next-line:no-any Doing "just enough" faking.
+  stackdriverLog: any;
+  constructor(options: MiddlewareOptions) {
+    passedOptions = options;
+    this.stackdriverLog = {
+      logging: {
+        auth: {
+          async getProjectId() {
+            return FAKE_PROJECT_ID;
+          }
+        }
+      }
+    };
+  }
+
+  // tslint:disable-next-line:no-any Doing "just enough" faking.
+  stream(level: any) {
+    return {level, type: 'raw', stream: this};
+  }
+}
+
+let passedProjectId: string|undefined;
+function fakeMakeMiddleware(
+    projectId: string, makeChildLogger: Function): Function {
+  passedProjectId = projectId;
+  return FAKE_GENERATED_MIDDLEWARE;
+}
+
+const {middleware, APP_LOG_SUFFIX} =
+    proxyquire('../../src/middleware/express', {
+      '../../src/index': {LoggingBunyan: FakeLoggingBunyan},
+      '@google-cloud/logging':
+          {middleware: {express: {makeMiddleware: fakeMakeMiddleware}}}
+    });
+
+describe('middleware/express', () => {
+  beforeEach(() => {
+    passedOptions = undefined;
+    passedProjectId = undefined;
+  });
+
+  it('should create and return a middleware', async () => {
+    const {mw} = await middleware();
+    assert.strictEqual(mw, FAKE_GENERATED_MIDDLEWARE);
+  });
+
+  it('should use default logName and level', async () => {
+    await middleware();
+    assert.ok(passedOptions);
+    assert.strictEqual(passedOptions!.logName, `bunyan_log_${APP_LOG_SUFFIX}`);
+    assert.strictEqual(passedOptions!.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!.logName, `${LOGNAME}_${APP_LOG_SUFFIX}`);
+    assert.strictEqual(passedOptions!.level, LEVEL);
+  });
+
+  it('should acquire the projectId and pass to makeMiddleware', async () => {
+    await middleware();
+    assert.strictEqual(passedProjectId, FAKE_PROJECT_ID);
+  });
+});