From 98e70a32cd6fcc6e2713176394285b4868ef8510 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Niklas=20Schl=C3=B6gel?= Date: Fri, 2 Feb 2024 12:36:14 +0100 Subject: [PATCH] feat: propagate operations (#842) --- src/common.ts | 14 ++++++++++ src/index.ts | 8 ++++++ src/middleware/express.ts | 7 ++++- src/middleware/make-child-logger.ts | 7 ++++- test/middleware/make-child-logger.ts | 40 ++++++++++++++++++++++++++-- 5 files changed, 72 insertions(+), 4 deletions(-) diff --git a/src/common.ts b/src/common.ts index d07c43f6..17529b08 100644 --- a/src/common.ts +++ b/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; diff --git a/src/index.ts b/src/index.ts index 6d81749e..7e43f4db 100644 --- a/src/index.ts +++ b/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; diff --git a/src/middleware/express.ts b/src/middleware/express.ts index b6ae61fa..2ccbf445 100644 --- a/src/middleware/express.ts +++ b/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', }); diff --git a/src/middleware/make-child-logger.ts b/src/middleware/make-child-logger.ts index d517bc3b..5e9a6d90 100644 --- a/src/middleware/make-child-logger.ts +++ b/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, }); } diff --git a/test/middleware/make-child-logger.ts b/test/middleware/make-child-logger.ts index ec5826d3..42d5cbf2 100644 --- a/test/middleware/make-child-logger.ts +++ b/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); }); });