From cb11e4c8e60ecbe0de33eddef2a91d4efd9d99d4 Mon Sep 17 00:00:00 2001
From: Ali Ijaz Sheikh <ofrobots@google.com>
Date: Tue, 18 Jun 2019 12:39:57 -0700
Subject: [PATCH] fix(middleware): need message in request log message (#349)

---
 README.md                              |  3 ++-
 src/middleware/express.ts              |  8 ++++++--
 system-test/test-middleware-express.ts | 27 +++++++++++++++++++-------
 3 files changed, 28 insertions(+), 10 deletions(-)

diff --git a/README.md b/README.md
index cf8840f1..f9ccfde0 100644
--- a/README.md
+++ b/README.md
@@ -126,7 +126,8 @@ app.get('/', (req, res) => {
     // `req.log` can be used as a winston style log method. All logs generated
     // using `req.log` use the current request context. That is, all logs
     // corresponding to a specific request will be bundled in the Stackdriver
-    // UI.
+    // UI. The log method will accept RFC5424 (syslog) log levels (the same
+    // levels provided by winston.config.syslog.levels).
     req.log.info('this is an info log message');
     res.send('hello world');
 });
diff --git a/src/middleware/express.ts b/src/middleware/express.ts
index 9d8acef7..aa964713 100644
--- a/src/middleware/express.ts
+++ b/src/middleware/express.ts
@@ -38,7 +38,7 @@ export async function middleware(options?: MiddlewareOptions) {
   const defaultOptions = {
     logName: 'winston_log',
     level: 'info',
-    levels: winston.config.npm.levels,
+    levels: winston.config.syslog.levels,
   };
   options = Object.assign({}, defaultOptions, options);
 
@@ -71,7 +71,11 @@ export async function middleware(options?: MiddlewareOptions) {
       transports: [loggingWinstonReq],
     });
     emitRequestLog = (httpRequest: HttpRequest, trace: string) => {
-      requestLogger.info({[LOGGING_TRACE_KEY]: trace, httpRequest});
+      requestLogger.info({
+        [LOGGING_TRACE_KEY]: trace,
+        httpRequest,
+        message: httpRequest.requestUrl || 'http request',
+      });
     };
   }
 
diff --git a/system-test/test-middleware-express.ts b/system-test/test-middleware-express.ts
index c200b7d3..720e99eb 100644
--- a/system-test/test-middleware-express.ts
+++ b/system-test/test-middleware-express.ts
@@ -62,13 +62,26 @@ describe(__filename, () => {
 
         await delay(WRITE_CONSISTENCY_DELAY_MS);
 
-        const log = logging.log(`${LOG_NAME}_applog`);
-        const entries = (await log.getEntries({pageSize: 1}))[0];
-        assert.strictEqual(entries.length, 1);
-        const entry = entries[0];
-        assert.strictEqual(LOG_MESSAGE, entry.data.message);
-        assert(entry.metadata.trace, 'should have a trace property');
-        assert(entry.metadata.trace.match(/projects\/.*\/traces\/.*/));
+        const appLog = logging.log(`${LOG_NAME}_applog`);
+        const appLogEntries = (await appLog.getEntries({pageSize: 1}))[0];
+        assert.strictEqual(appLogEntries.length, 1);
+        const [appLogEntry] = appLogEntries;
+        assert.strictEqual(LOG_MESSAGE, appLogEntry.data.message);
+        assert(appLogEntry.metadata.trace, 'should have a trace property');
+        assert(appLogEntry.metadata.trace.match(/projects\/.*\/traces\/.*/));
+        assert.strictEqual(appLogEntry.metadata.severity, 'INFO');
+
+        const requestLog = logging.log(LOG_NAME);
+        const requestLogEntries = (await requestLog.getEntries({
+          pageSize: 1,
+        }))[0];
+        assert.strictEqual(requestLogEntries.length, 1);
+        const [requestLogEntry] = requestLogEntries;
+        assert.strictEqual(
+          requestLogEntry.metadata.trace,
+          appLogEntry.metadata.trace
+        );
+
         done();
       };