fix: wrap the Reliability Kit logger

We have been losing information from the OpenTelemetry internal logs
because they log multiple messages in a row which pino/reliability kit
does not support. We don't support this because we want to maintain
consistency with n-logger.

To fix this, we need to wrap the Reliability Kit logger and extract any
extra logged information into a new property. I've gone with `details`.
Testing this locally, it's not common to get any info but it's important
when we do get it - it helped me debug the issue with loading Pino ahead
of instrumentation.

Author: rowanmanning

packages/opentelemetry/lib/index.js

@@ -44,19 +44,18 @@ function setupOpenTelemetry({
 		});
 	}
 
-	// Use a Reliability Kit logger for logging. The DiagLogLevel
-	// does nothing here – Reliability Kit's log level (set through
-	// the LOG_LEVEL environment variable) takes over. We set the
-	// OpenTelemetry log level to the maximum value that we want
-	// Reliability Kit to consider logging
-	opentelemetry.api.diag.setLogger(
-		// @ts-ignore this complains because DiagLogger accepts a type
-		// of unknown whereas our logger is stricter. This is fine though,
-		// if something unknown is logged then we do our best with it.
-		// It's easier to ignore this error than fix it.
-		logger.createChildLogger({ event: 'OTEL_INTERNALS' }),
-		opentelemetry.api.DiagLogLevel.INFO
-	);
+	// We need to create a new logger for OpenTelemetry internals
+	// because the function signature is different and OpenTelemetry
+	// logs mutliple strings. With pino this means we lose data
+	const log = logger.createChildLogger({ event: 'OTEL_INTERNALS' });
+	const opentelemetryLogger = {
+		error: (...args) => log.error(args[0], { details: args.slice(1) }),
+		info: (...args) => log.info(args[0], { details: args.slice(1) }),
+		warn: (...args) => log.warn(args[0], { details: args.slice(1) }),
+		debug: () => {},
+		verbose: () => {}
+	};
+	opentelemetry.api.diag.setLogger(opentelemetryLogger);
 
 	// Set up and start OpenTelemetry
 	instances = {

packages/opentelemetry/test/unit/lib/index.spec.js

@@ -24,6 +24,7 @@ describe('@dotcom-reliability-kit/opentelemetry', () => {
 	let createTracingConfig;
 	let HostMetrics;
 	let logger;
+	let mockChildLogger;
 	let NodeSDK;
 	let opentelemetry;
 
@@ -46,7 +47,14 @@ describe('@dotcom-reliability-kit/opentelemetry', () => {
 		NodeSDK = require('@opentelemetry/sdk-node').NodeSDK;
 		logger = require('@dotcom-reliability-kit/logger');
 
-		logger.createChildLogger.mockReturnValue('mock child logger');
+		mockChildLogger = {
+			debug: jest.fn(),
+			error: jest.fn(),
+			info: jest.fn(),
+			verbose: jest.fn(),
+			warn: jest.fn()
+		};
+		logger.createChildLogger.mockReturnValue(mockChildLogger);
 		api.DiagLogLevel.INFO = 'mock info log level';
 
 		opentelemetry = require('../../../lib/index');
@@ -69,18 +77,76 @@ describe('@dotcom-reliability-kit/opentelemetry', () => {
 			});
 		});
 
-		it('sets up OpenTelemetry to log via Reliability Kit logger', () => {
+		it('sets up OpenTelemetry to log via a custom logger', () => {
 			expect(logger.createChildLogger).toHaveBeenCalledTimes(1);
 			expect(logger.createChildLogger).toHaveBeenCalledWith({
 				event: 'OTEL_INTERNALS'
 			});
 			expect(api.diag.setLogger).toHaveBeenCalledTimes(1);
+			expect(api.diag.setLogger).not.toHaveBeenCalledWith(mockChildLogger);
 			expect(api.diag.setLogger).toHaveBeenCalledWith(
-				'mock child logger',
-				'mock info log level'
+				expect.objectContaining({
+					debug: expect.any(Function),
+					error: expect.any(Function),
+					info: expect.any(Function),
+					verbose: expect.any(Function),
+					warn: expect.any(Function)
+				})
 			);
 		});
 
+		describe('custom logger', () => {
+			let customLogger;
+
+			beforeEach(() => {
+				customLogger = api.diag.setLogger.mock.calls[0][0];
+			});
+
+			describe('.debug()', () => {
+				it('does nothing', () => {
+					customLogger.debug('mock message 1', 'mock message 2');
+					expect(mockChildLogger.debug).toHaveBeenCalledTimes(0);
+				});
+			});
+
+			describe('.error()', () => {
+				it('logs an error via the Reliability Kit child logger', () => {
+					customLogger.error('mock message 1', 'mock message 2');
+					expect(mockChildLogger.error).toHaveBeenCalledTimes(1);
+					expect(mockChildLogger.error).toHaveBeenCalledWith('mock message 1', {
+						details: ['mock message 2']
+					});
+				});
+			});
+
+			describe('.info()', () => {
+				it('logs info via the Reliability Kit child logger', () => {
+					customLogger.info('mock message 1', 'mock message 2');
+					expect(mockChildLogger.info).toHaveBeenCalledTimes(1);
+					expect(mockChildLogger.info).toHaveBeenCalledWith('mock message 1', {
+						details: ['mock message 2']
+					});
+				});
+			});
+
+			describe('.verbose()', () => {
+				it('does nothing', () => {
+					customLogger.verbose('mock message 1', 'mock message 2');
+					expect(mockChildLogger.verbose).toHaveBeenCalledTimes(0);
+				});
+			});
+
+			describe('.warn()', () => {
+				it('logs an warning via the Reliability Kit child logger', () => {
+					customLogger.warn('mock message 1', 'mock message 2');
+					expect(mockChildLogger.warn).toHaveBeenCalledTimes(1);
+					expect(mockChildLogger.warn).toHaveBeenCalledWith('mock message 1', {
+						details: ['mock message 2']
+					});
+				});
+			});
+		});
+
 		it('configures the OpenTelemetry instrumentations', () => {
 			expect(createInstrumentationConfig).toHaveBeenCalledTimes(1);
 			expect(createInstrumentationConfig).toHaveBeenCalledWith();