feat: propagate operations (#842)

src/common.ts

@@ -30,6 +30,8 @@ import mapValues = require('lodash.mapvalues');
 import {Options} from '.';
 import {Entry, LogEntry} from '@google-cloud/logging/build/src/entry';
 import {LogSyncOptions} from '@google-cloud/logging/build/src/log-sync';
+import {google} from '@google-cloud/logging/build/protos/protos';
+import ILogEntryOperation = google.logging.v2.ILogEntryOperation;
 
 type Callback = (err: Error | null, apiResponse?: {}) => void;
 export type MonitoredResource = protos.google.api.MonitoredResource;
@@ -90,6 +92,11 @@ export const LOGGING_SPAN_KEY = 'logging.googleapis.com/spanId';
  */
 export const LOGGING_SAMPLED_KEY = 'logging.googleapis.com/trace_sampled';
 
+/*!
+ * Log entry data key to allow users to indicate operation details for the request.
+ */
+export const LOGGING_OPERATION_KEY = 'logging.googleapis.com/operation';
+
 /**
  * Default library version to be used
  * Using release-please annotations to update DEFAULT_INSTRUMENTATION_VERSION with latest version.
@@ -280,6 +287,12 @@ export class LoggingCommon {
       entryMetadata.traceSampled = metadata[LOGGING_SAMPLED_KEY] === true;
     }
 
+    if (LOGGING_OPERATION_KEY in metadata) {
+      entryMetadata.operation = metadata[
+        LOGGING_OPERATION_KEY
+      ] as ILogEntryOperation;
+    }
+
     // 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
@@ -292,6 +305,7 @@ export class LoggingCommon {
       delete data.metadata![LOGGING_TRACE_KEY];
       delete data.metadata![LOGGING_SPAN_KEY];
       delete data.metadata![LOGGING_SAMPLED_KEY];
+      delete data.metadata![LOGGING_OPERATION_KEY];
       delete data.metadata!.httpRequest;
       delete data.metadata!.labels;
       delete data.metadata!.timestamp;

src/index.ts

@@ -18,6 +18,7 @@ import {
   LOGGING_TRACE_KEY as COMMON_TRACE_KEY,
   LOGGING_SPAN_KEY as COMMON_SPAN_KEY,
   LOGGING_SAMPLED_KEY as COMMON_SAMPLED_KEY,
+  LOGGING_OPERATION_KEY as COMMON_OPERATION_KEY,
   LoggingCommon,
   getCurrentTraceFromAgent,
 } from './common';
@@ -199,6 +200,7 @@ 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;
+  static readonly LOGGING_OPERATIONS_KEY = COMMON_OPERATION_KEY;
 
   common: LoggingCommon;
 
@@ -242,3 +244,9 @@ export const LOGGING_SPAN_KEY = COMMON_SPAN_KEY;
 // 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/rpc/google.logging.v2#logentry
 export const LOGGING_SAMPLED_KEY = COMMON_SAMPLED_KEY;
+
+// LOGGING_OPERATIONS_KEY is Cloud Logging specific and has the format:
+// logging.googleapis.com/operation
+// The value of this field is an object with optional producer, id, first and last parameters.
+// For more information, see: https://cloud.google.com/logging/docs/reference/v2/rpc/google.logging.v2#logentryoperation
+export const LOGGING_OPERATION_KEY = COMMON_OPERATION_KEY;

src/middleware/express.ts

@@ -25,9 +25,12 @@ import {
   LOGGING_TRACE_KEY,
   LOGGING_SPAN_KEY,
   LOGGING_SAMPLED_KEY,
+  LOGGING_OPERATION_KEY,
 } from '../common';
 import {LoggingWinston, Options} from '../index';
 import {makeChildLogger} from './make-child-logger';
+import {google} from '@google-cloud/logging/build/protos/protos';
+import ILogEntryOperation = google.logging.v2.ILogEntryOperation;
 
 export const REQUEST_LOG_SUFFIX = '_reqlog';
 
@@ -100,7 +103,8 @@ export async function makeMiddleware(
       httpRequest: HttpRequest,
       trace: string,
       span?: string,
-      sampled?: boolean
+      sampled?: boolean,
+      operation?: ILogEntryOperation
     ) => {
       logger.info({
         // The request logs must have a log name distinct from the app logs
@@ -109,6 +113,7 @@ export async function makeMiddleware(
         [LOGGING_TRACE_KEY]: trace,
         [LOGGING_SPAN_KEY]: span,
         [LOGGING_SAMPLED_KEY]: sampled,
+        [LOGGING_OPERATION_KEY]: operation,
         httpRequest,
         message: httpRequest.requestUrl || 'http request',
       });

src/middleware/make-child-logger.ts

@@ -17,17 +17,22 @@ import {
   LOGGING_TRACE_KEY,
   LOGGING_SPAN_KEY,
   LOGGING_SAMPLED_KEY,
+  LOGGING_OPERATION_KEY,
 } from '../index';
+import {google} from '@google-cloud/logging/build/protos/protos';
+import ILogEntryOperation = google.logging.v2.ILogEntryOperation;
 
 export function makeChildLogger(
   logger: winston.Logger,
   trace: string,
   span?: string,
-  sampled?: boolean
+  sampled?: boolean,
+  operation?: ILogEntryOperation
 ) {
   return logger.child({
     [LOGGING_TRACE_KEY]: trace,
     [LOGGING_SPAN_KEY]: span,
     [LOGGING_SAMPLED_KEY]: sampled,
+    [LOGGING_OPERATION_KEY]: operation,
   });
 }

test/middleware/make-child-logger.ts

@@ -19,14 +19,18 @@ import {
   LOGGING_TRACE_KEY,
   LOGGING_SPAN_KEY,
   LOGGING_SAMPLED_KEY,
+  LOGGING_OPERATION_KEY,
 } from '../../src/common';
 
 import {makeChildLogger} from '../../src/middleware/make-child-logger';
+import {google} from '@google-cloud/logging/build/protos/protos';
+import ILogEntryOperation = google.logging.v2.ILogEntryOperation;
 
 describe('makeChildLogger', () => {
   const FAKE_TRACE = '🤥';
   const FAKE_SPAN = '☂️';
   const FAKE_SAMPLE = true;
+  const FAKE_OPERATION: ILogEntryOperation = {id: 'some-operation'};
   const LOGGER = winston.createLogger({
     transports: [new winston.transports.Console({silent: true})],
   });
@@ -108,22 +112,54 @@ describe('makeChildLogger', () => {
     assert.strictEqual(sample, FAKE_SAMPLE);
   });
 
+  it('should inject the LOGGING_OPERATION_KEY into the metadata', () => {
+    const child = makeChildLogger(
+      LOGGER,
+      FAKE_TRACE,
+      FAKE_SPAN,
+      FAKE_SAMPLE,
+      FAKE_OPERATION
+    );
+    let trace, span, sample, operation;
+    // 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];
+      operation = info[LOGGING_OPERATION_KEY];
+    };
+    child.debug('hello world');
+    assert.strictEqual(trace, FAKE_TRACE);
+    assert.strictEqual(span, FAKE_SPAN);
+    assert.strictEqual(sample, FAKE_SAMPLE);
+    assert.strictEqual(operation, FAKE_OPERATION);
+  });
+
   it('should not overwrite existing LOGGING_X_KEY values', () => {
-    const child = makeChildLogger(LOGGER, FAKE_TRACE, FAKE_SPAN, FAKE_SAMPLE);
-    let trace, span, sample;
+    const child = makeChildLogger(
+      LOGGER,
+      FAKE_TRACE,
+      FAKE_SPAN,
+      FAKE_SAMPLE,
+      FAKE_OPERATION
+    );
+    let trace, span, sample, operation;
     // 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];
+      operation = info[LOGGING_OPERATION_KEY];
     };
     child.debug('hello world', {
       [LOGGING_TRACE_KEY]: 'to-be-clobbered',
       [LOGGING_SPAN_KEY]: 'to-be-clobbered',
       [LOGGING_SAMPLED_KEY]: false,
+      [LOGGING_OPERATION_KEY]: {id: 'some-other-operation'},
     });
     assert.notStrictEqual(trace, FAKE_TRACE);
     assert.notStrictEqual(span, FAKE_SPAN);
     assert.notStrictEqual(sample, FAKE_SAMPLE);
+    assert.notStrictEqual(operation, FAKE_OPERATION);
   });
 });