feat: propagate spanIds (#599)

Fixes #597 🦕 Blocked: [Nodejs-logging release](googleapis/nodejs-logging#1092) Changes: - Users can now hardcode a spanId via `LOGGING_SPAN_KEY` when using Winston - Middleware scenario: if span is detected from the request obj, it is propagated to makeChildLogger, and emitRequestLog capabilities, and span is included in the final child logs. - Fix e2e tests given `originalUrl` needs to be a real url - export function `getCurrentTraceFromAgent`
googleapis · Jun 14, 2021 · 6a34151 · 6a34151
1 parent 349bdec
commit 6a34151
Show file tree

Hide file tree

Showing 9 changed files with 170 additions and 18 deletions.
diff --git a/.readme-partials.yaml b/.readme-partials.yaml
@@ -130,7 +130,7 @@ body: |-
 
     ![Logs in Trace Example](https://raw.githubusercontent.com/googleapis/nodejs-logging-winston/master/doc/images/winston-logs-in-trace.png)
 
-    If you wish to set the LogEntry `trace` property with a custom value, then set a winston metadata property for `'logging.googleapis.com/trace'`, which is exported by this module as `LOGGING_TRACE_KEY`. For example:
+    If you wish to set the LogEntry `trace`, `spanId`, and `traceSampled` properties with custom values, then set Winston metadata properties for `'logging.googleapis.com/trace'`, `'logging.googleapis.com/spanId'`, `'logging.googleapis.com/trace_sampled'`, which is exported by this module as `LOGGING_TRACE_KEY`, `LOGGING_SPAN_KEY`, and `LOGGING_SAMPLED_KEY` respectively. For example:
 
     ```js
     const winston = require('winston');
@@ -140,6 +140,8 @@ body: |-
 
     winston.info('Log entry with custom trace value', {
     [LoggingWinston.LOGGING_TRACE_KEY]: 'custom-trace-value'
+    [LoggingWinston.LOGGING_SPAN_KEY]: 'custom-span-value'
+    [LoggingWinston.LOGGING_SAMPLED_KEY]: true
     });
     ```
 

diff --git a/README.md b/README.md
@@ -208,7 +208,7 @@ If you use [@google-cloud/trace-agent][trace-agent] module, then this module wil
 
 ![Logs in Trace Example](https://raw.githubusercontent.com/googleapis/nodejs-logging-winston/master/doc/images/winston-logs-in-trace.png)
 
-If you wish to set the LogEntry `trace` property with a custom value, then set a winston metadata property for `'logging.googleapis.com/trace'`, which is exported by this module as `LOGGING_TRACE_KEY`. For example:
+If you wish to set the LogEntry `trace`, `spanId`, and `traceSampled` properties with custom values, then set Winston metadata properties for `'logging.googleapis.com/trace'`, `'logging.googleapis.com/spanId'`, `'logging.googleapis.com/trace_sampled'`, which is exported by this module as `LOGGING_TRACE_KEY`, `LOGGING_SPAN_KEY`, and `LOGGING_SAMPLED_KEY` respectively. For example:
 
 ```js
 const winston = require('winston');
@@ -218,6 +218,8 @@ const {LoggingWinston} = require('@google-cloud/logging-winston');
 
 winston.info('Log entry with custom trace value', {
 [LoggingWinston.LOGGING_TRACE_KEY]: 'custom-trace-value'
+[LoggingWinston.LOGGING_SPAN_KEY]: 'custom-span-value'
+[LoggingWinston.LOGGING_SAMPLED_KEY]: true
 });
 ```
 

diff --git a/src/common.ts b/src/common.ts
@@ -71,12 +71,22 @@ const STACKDRIVER_LOGGING_LEVEL_CODE_TO_NAME: {
  */
 export const LOGGING_TRACE_KEY = 'logging.googleapis.com/trace';
 
+/*!
+ * Log entry data key to allow users to indicate a spanId for the request.
+ */
+export const LOGGING_SPAN_KEY = 'logging.googleapis.com/spanId';
+
+/*!
+ * Log entry data key to allow users to indicate a traceSampled flag for the request.
+ */
+export const LOGGING_SAMPLED_KEY = 'logging.googleapis.com/trace_sampled';
+
 /*!
  * Gets the current fully qualified trace ID when available from the
  * @google-cloud/trace-agent library in the LogEntry.trace field format of:
  * "projects/[PROJECT-ID]/traces/[TRACE-ID]".
  */
-function getCurrentTraceFromAgent(): string | null {
+export function getCurrentTraceFromAgent(): string | null {
   // eslint-disable-next-line @typescript-eslint/no-explicit-any
   const agent = (global as any)._google_trace_agent;
   if (!agent || !agent.getCurrentContextId || !agent.getWriterProjectId) {
@@ -105,7 +115,12 @@ export class LoggingCommon {
   private serviceContext: ServiceContext | undefined;
   private prefix: string | undefined;
   private labels: object | undefined;
+  // LOGGING_TRACE_KEY is Cloud Logging specific and has the format:
+  // logging.googleapis.com/trace
   static readonly LOGGING_TRACE_KEY = LOGGING_TRACE_KEY;
+  // LOGGING_TRACE_KEY is Cloud Logging specific and has the format:
+  // logging.googleapis.com/spanId
+  static readonly LOGGING_SPAN_KEY = LOGGING_SPAN_KEY;
 
   constructor(options?: Options) {
     options = Object.assign(
@@ -213,6 +228,15 @@ export class LoggingCommon {
       entryMetadata.trace = trace as string;
     }
 
+    const spanId = metadata[LOGGING_SPAN_KEY];
+    if (spanId) {
+      entryMetadata.spanId = spanId as string;
+    }
+
+    if (LOGGING_SAMPLED_KEY in metadata) {
+      entryMetadata.traceSampled = metadata[LOGGING_SAMPLED_KEY] === '1';
+    }
+
     // we have tests that assert that metadata is always passed.
     // not sure if its correct but for now we always set it even if it has
     // nothing in it
@@ -223,6 +247,8 @@ export class LoggingCommon {
     if (hasMetadata) {
       // clean entryMetadata props
       delete data.metadata![LOGGING_TRACE_KEY];
+      delete data.metadata![LOGGING_SPAN_KEY];
+      delete data.metadata![LOGGING_SAMPLED_KEY];
       delete data.metadata!.httpRequest;
       delete data.metadata!.labels;
       delete data.metadata!.timestamp;

diff --git a/src/index.ts b/src/index.ts
@@ -14,7 +14,13 @@
 
 import TransportStream = require('winston-transport');
 
-import {LOGGING_TRACE_KEY as COMMON_TRACE_KEY, LoggingCommon} from './common';
+import {
+  LOGGING_TRACE_KEY as COMMON_TRACE_KEY,
+  LOGGING_SPAN_KEY as COMMON_SPAN_KEY,
+  LOGGING_SAMPLED_KEY as COMMON_SAMPLED_KEY,
+  LoggingCommon,
+  getCurrentTraceFromAgent,
+} from './common';
 import * as express from './middleware/express';
 import {getDefaultMetadataForTracing} from './default-metadata';
 import {
@@ -28,6 +34,7 @@ const LEVEL = Symbol.for('level');
 // Export the express middleware as 'express'.
 export {express};
 export {getDefaultMetadataForTracing};
+export {getCurrentTraceFromAgent};
 
 type Callback = (err: Error | null, apiResponse?: {}) => void;
 
@@ -160,6 +167,8 @@ export interface Options extends LoggingOptions {
  */
 export class LoggingWinston extends TransportStream {
   static readonly LOGGING_TRACE_KEY = COMMON_TRACE_KEY;
+  static readonly LOGGING_SPAN_KEY = COMMON_SPAN_KEY;
+  static readonly LOGGING_SAMPLED_KEY = COMMON_SAMPLED_KEY;
 
   common: LoggingCommon;
 
@@ -184,4 +193,18 @@ export class LoggingWinston extends TransportStream {
   }
 }
 
+// LOGGING_TRACE_KEY is Cloud Logging specific and has the format:
+// logging.googleapis.com/trace
+// For more information, see: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#FIELDS.trace
 export const LOGGING_TRACE_KEY = COMMON_TRACE_KEY;
+
+// LOGGING_SPAN_KEY is Cloud Logging specific and has the format:
+// logging.googleapis.com/spanId
+// For more information, see: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#FIELDS.span_id
+export const LOGGING_SPAN_KEY = COMMON_SPAN_KEY;
+
+// LOGGING_SAMPLED_KEY is Cloud Logging specific and has the format:
+// logging.googleapis.com/trace_sampled
+// The value of this field must be either true or false. For more information,
+// see traceSampled on the LogEntry page:	https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#FIELDS.trace_sampled
+export const LOGGING_SAMPLED_KEY = COMMON_SAMPLED_KEY;
diff --git a/src/middleware/express.ts b/src/middleware/express.ts
@@ -20,7 +20,11 @@ import {
 import {GCPEnv} from 'google-auth-library';
 import * as winston from 'winston';
 
-import {LOGGING_TRACE_KEY} from '../common';
+import {
+  LOGGING_TRACE_KEY,
+  LOGGING_SPAN_KEY,
+  LOGGING_SAMPLED_KEY,
+} from '../common';
 import {LoggingWinston, Options} from '../index';
 import {makeChildLogger} from './make-child-logger';
 
@@ -77,12 +81,19 @@ export async function makeMiddleware(
       `${transport.common.logName}${REQUEST_LOG_SUFFIX}`
     );
 
-    emitRequestLogEntry = (httpRequest: HttpRequest, trace: string) => {
+    emitRequestLogEntry = (
+      httpRequest: HttpRequest,
+      trace: string,
+      span?: string,
+      sampled?: boolean
+    ) => {
       logger.info({
         // The request logs must have a log name distinct from the app logs
         // for log correlation to work.
         logName: requestLogName,
         [LOGGING_TRACE_KEY]: trace,
+        [LOGGING_SPAN_KEY]: span,
+        [LOGGING_SAMPLED_KEY]: sampled,
         httpRequest,
         message: httpRequest.requestUrl || 'http request',
       });
@@ -91,7 +102,8 @@ export async function makeMiddleware(
 
   return commonMiddleware.express.makeMiddleware(
     projectId,
-    (trace: string) => makeChildLogger(logger, trace),
+    (trace: string, span?: string, sampled?: boolean) =>
+      makeChildLogger(logger, trace, span, sampled),
     emitRequestLogEntry
   );
 }
diff --git a/src/middleware/make-child-logger.ts b/src/middleware/make-child-logger.ts
@@ -13,8 +13,21 @@
 // limitations under the License.
 
 import * as winston from 'winston';
-import {LOGGING_TRACE_KEY} from '../index';
+import {
+  LOGGING_TRACE_KEY,
+  LOGGING_SPAN_KEY,
+  LOGGING_SAMPLED_KEY,
+} from '../index';
 
-export function makeChildLogger(logger: winston.Logger, trace: string) {
-  return logger.child({[LOGGING_TRACE_KEY]: trace});
+export function makeChildLogger(
+  logger: winston.Logger,
+  trace: string,
+  span?: string,
+  sampled?: boolean
+) {
+  return logger.child({
+    [LOGGING_TRACE_KEY]: trace,
+    [LOGGING_SPAN_KEY]: span,
+    [LOGGING_SAMPLED_KEY]: sampled,
+  });
 }
diff --git a/system-test/test-middleware-express.ts b/system-test/test-middleware-express.ts
@@ -71,7 +71,7 @@ describe(__filename, () => {
             'user-agent': 'Mocha/test-case',
           },
           statusCode: 200,
-          originalUrl: '/foo/bar',
+          originalUrl: 'http://google.com',
           method: 'PUSH',
         };
         const fakeResponse = {
@@ -96,6 +96,9 @@ describe(__filename, () => {
           assert.strictEqual(LOG_MESSAGE, appLogEntry.data.message);
           assert(appLogEntry.metadata.trace, 'should have a trace property');
           assert(appLogEntry.metadata.trace!.match(/projects\/.*\/traces\/.*/));
+          assert(appLogEntry.metadata.spanId, 'should have a span property');
+          assert(appLogEntry.metadata.spanId!.match(/^[0-9]*/));
+          assert.strictEqual(appLogEntry.metadata.traceSampled, false);
           assert.strictEqual(appLogEntry.metadata.severity, 'INFO');
 
           const requestLog = logging.log(`${LOG_NAME}${REQUEST_LOG_SUFFIX}`);

diff --git a/test/common.ts b/test/common.ts
@@ -345,17 +345,46 @@ describe('logging-common', () => {
       loggingCommon.log(LEVEL, MESSAGE, metadataWithLabels, assert.ifError);
     });
 
-    it('should promote prefixed trace property to metadata', done => {
+    it('should promote prefixed trace properties to metadata', done => {
       const metadataWithTrace = Object.assign({}, METADATA);
       const loggingTraceKey = loggingCommonLib.LOGGING_TRACE_KEY;
+      const loggingSpanKey = loggingCommonLib.LOGGING_SPAN_KEY;
+      const loggingSampledKey = loggingCommonLib.LOGGING_SAMPLED_KEY;
       // metadataWithTrace does not have index signature.
       // eslint-disable-next-line @typescript-eslint/no-explicit-any
       (metadataWithTrace as any)[loggingTraceKey] = 'trace1';
+      // eslint-disable-next-line @typescript-eslint/no-explicit-any
+      (metadataWithTrace as any)[loggingSpanKey] = 'span1';
+      // eslint-disable-next-line @typescript-eslint/no-explicit-any
+      (metadataWithTrace as any)[loggingSampledKey] = '1';
 
       loggingCommon.stackdriverLog.entry = (entryMetadata: {}, data: {}) => {
         assert.deepStrictEqual(entryMetadata, {
           resource: loggingCommon.resource,
           trace: 'trace1',
+          spanId: 'span1',
+          traceSampled: true,
+        });
+        assert.deepStrictEqual(data, {
+          message: MESSAGE,
+          metadata: METADATA,
+        });
+        done();
+      };
+      loggingCommon.log(LEVEL, MESSAGE, metadataWithTrace, assert.ifError);
+    });
+
+    it('should promote a false traceSampled value to metadata', done => {
+      const metadataWithTrace = Object.assign({}, METADATA);
+      const loggingSampledKey = loggingCommonLib.LOGGING_SAMPLED_KEY;
+      // metadataWithTrace does not have index signature.
+      // eslint-disable-next-line @typescript-eslint/no-explicit-any
+      (metadataWithTrace as any)[loggingSampledKey] = '0';
+
+      loggingCommon.stackdriverLog.entry = (entryMetadata: {}, data: {}) => {
+        assert.deepStrictEqual(entryMetadata, {
+          resource: loggingCommon.resource,
+          traceSampled: false,
         });
         assert.deepStrictEqual(data, {
           message: MESSAGE,

diff --git a/test/middleware/make-child-logger.ts b/test/middleware/make-child-logger.ts
@@ -15,12 +15,18 @@
 import * as assert from 'assert';
 import {describe, it, afterEach} from 'mocha';
 import * as winston from 'winston';
-import {LOGGING_TRACE_KEY} from '../../src/common';
+import {
+  LOGGING_TRACE_KEY,
+  LOGGING_SPAN_KEY,
+  LOGGING_SAMPLED_KEY,
+} from '../../src/common';
 
 import {makeChildLogger} from '../../src/middleware/make-child-logger';
 
 describe('makeChildLogger', () => {
   const FAKE_TRACE = '🤥';
+  const FAKE_SPAN = '☂️';
+  const FAKE_SAMPLE = true;
   const LOGGER = winston.createLogger({
     transports: [new winston.transports.Console({silent: true})],
   });
@@ -63,7 +69,7 @@ describe('makeChildLogger', () => {
     assert.notStrictEqual(child.write, LOGGER.write);
   });
 
-  it('should inject the LOGGING_TRACE_KEY into the metadata', () => {
+  it('should inject LOGGING_TRACE_KEY only into the metadata', () => {
     const child = makeChildLogger(LOGGER, FAKE_TRACE);
     let trace;
     // eslint-disable-next-line @typescript-eslint/no-explicit-any
@@ -74,14 +80,50 @@ describe('makeChildLogger', () => {
     assert.strictEqual(trace, FAKE_TRACE);
   });
 
-  it('should not overwrite existing LOGGING_TRACE_KEY value', () => {
-    const child = makeChildLogger(LOGGER, FAKE_TRACE);
-    let trace;
+  it('should inject the LOGGING_SPAN_KEY into the metadata', () => {
+    const child = makeChildLogger(LOGGER, FAKE_TRACE, FAKE_SPAN);
+    let trace, span;
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    (LOGGER.write as any) = (info: winston.LogEntry) => {
+      trace = info[LOGGING_TRACE_KEY];
+      span = info[LOGGING_SPAN_KEY];
+    };
+    child.debug('hello world');
+    assert.strictEqual(trace, FAKE_TRACE);
+    assert.strictEqual(span, FAKE_SPAN);
+  });
+
+  it('should inject the LOGGING_SAMPLED_KEY into the metadata', () => {
+    const child = makeChildLogger(LOGGER, FAKE_TRACE, FAKE_SPAN, FAKE_SAMPLE);
+    let trace, span, sample;
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    (LOGGER.write as any) = (info: winston.LogEntry) => {
+      trace = info[LOGGING_TRACE_KEY];
+      span = info[LOGGING_SPAN_KEY];
+      sample = info[LOGGING_SAMPLED_KEY];
+    };
+    child.debug('hello world');
+    assert.strictEqual(trace, FAKE_TRACE);
+    assert.strictEqual(span, FAKE_SPAN);
+    assert.strictEqual(sample, FAKE_SAMPLE);
+  });
+
+  it('should not overwrite existing LOGGING_X_KEY values', () => {
+    const child = makeChildLogger(LOGGER, FAKE_TRACE, FAKE_SPAN, FAKE_SAMPLE);
+    let trace, span, sample;
     // eslint-disable-next-line @typescript-eslint/no-explicit-any
     (LOGGER.write as any) = (info: winston.LogEntry) => {
       trace = info[LOGGING_TRACE_KEY];
+      span = info[LOGGING_SPAN_KEY];
+      sample = info[LOGGING_SAMPLED_KEY];
     };
-    child.debug('hello world', {[LOGGING_TRACE_KEY]: 'to-be-clobbered'});
+    child.debug('hello world', {
+      [LOGGING_TRACE_KEY]: 'to-be-clobbered',
+      [LOGGING_SPAN_KEY]: 'to-be-clobbered',
+      [LOGGING_SAMPLED_KEY]: '0',
+    });
     assert.notStrictEqual(trace, FAKE_TRACE);
+    assert.notStrictEqual(span, FAKE_SPAN);
+    assert.notStrictEqual(sample, FAKE_SAMPLE);
   });
 });