diff --git a/api/package-lock.json b/api/package-lock.json index 02afd3ed987c..9adf22672bb8 100644 --- a/api/package-lock.json +++ b/api/package-lock.json @@ -27,6 +27,8 @@ "@json2csv/node": "^7.0.2", "@opentelemetry/api": "^1.9.1", "@opentelemetry/exporter-metrics-otlp-proto": "^0.220.0", + "@opentelemetry/api-logs": "^0.215.0", + "@opentelemetry/exporter-logs-otlp-proto": "^0.215.0", "@opentelemetry/exporter-trace-otlp-proto": "^0.215.0", "@opentelemetry/instrumentation-fs": "^0.39.0", "@opentelemetry/instrumentation-host-metrics": "^0.3.0", @@ -35,6 +37,7 @@ "@opentelemetry/instrumentation-undici": "^0.30.0", "@opentelemetry/resource-detector-container": "^0.8.11", "@opentelemetry/resources": "^2.9.0", + "@opentelemetry/sdk-logs": "^0.215.0", "@opentelemetry/sdk-node": "^0.215.0", "@opentelemetry/semantic-conventions": "^1.40.0", "@pdf-lib/fontkit": "^1.1.1", diff --git a/api/package.json b/api/package.json index 40a692fe4bfd..c2043b950f77 100644 --- a/api/package.json +++ b/api/package.json @@ -109,6 +109,8 @@ "@json2csv/node": "^7.0.2", "@opentelemetry/api": "^1.9.1", "@opentelemetry/exporter-metrics-otlp-proto": "^0.220.0", + "@opentelemetry/api-logs": "^0.215.0", + "@opentelemetry/exporter-logs-otlp-proto": "^0.215.0", "@opentelemetry/exporter-trace-otlp-proto": "^0.215.0", "@opentelemetry/instrumentation-fs": "^0.39.0", "@opentelemetry/instrumentation-host-metrics": "^0.3.0", @@ -117,6 +119,7 @@ "@opentelemetry/instrumentation-undici": "^0.30.0", "@opentelemetry/resource-detector-container": "^0.8.11", "@opentelemetry/resources": "^2.9.0", + "@opentelemetry/sdk-logs": "^0.215.0", "@opentelemetry/sdk-node": "^0.215.0", "@opentelemetry/semantic-conventions": "^1.40.0", "@pdf-lib/fontkit": "^1.1.1", diff --git a/api/src/shared/infrastructure/open-telemetry/initialize-open-telemetry.js b/api/src/shared/infrastructure/open-telemetry/initialize-open-telemetry.js index 512647970478..6ee8934ceceb 100644 --- a/api/src/shared/infrastructure/open-telemetry/initialize-open-telemetry.js +++ b/api/src/shared/infrastructure/open-telemetry/initialize-open-telemetry.js @@ -1,4 +1,5 @@ import { diag, DiagLogLevel } from '@opentelemetry/api'; +import { OTLPLogExporter } from '@opentelemetry/exporter-logs-otlp-proto'; import { OTLPMetricExporter } from '@opentelemetry/exporter-metrics-otlp-proto'; import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-proto'; import { FsInstrumentation } from '@opentelemetry/instrumentation-fs'; @@ -8,6 +9,7 @@ import { PgInstrumentation } from '@opentelemetry/instrumentation-pg'; import { UndiciInstrumentation } from '@opentelemetry/instrumentation-undici'; import { containerDetector } from '@opentelemetry/resource-detector-container'; import { envDetector, hostDetector, osDetector, processDetector } from '@opentelemetry/resources'; +import { BatchLogRecordProcessor } from '@opentelemetry/sdk-logs'; import { NodeSDK, resources } from '@opentelemetry/sdk-node'; import { ATTR_SERVICE_NAME } from '@opentelemetry/semantic-conventions'; @@ -26,9 +28,10 @@ export function initializeOpenTelemetry(serviceName) { ...logger, verbose: logger.debug, }, - DiagLogLevel.DEBUG, + DiagLogLevel.WARN, ); + const logExporter = new OTLPLogExporter(); const traceExporter = new OTLPTraceExporter(); const metricExporter = new OTLPMetricExporter(); @@ -39,6 +42,7 @@ export function initializeOpenTelemetry(serviceName) { resourceDetectors: [envDetector, hostDetector, osDetector, processDetector, containerDetector, scalingoDetector], traceExporter, metricExporter, + logRecordProcessors: [new BatchLogRecordProcessor(logExporter)], instrumentations: [ new HostMetricsInstrumentation(), new HttpInstrumentation(), diff --git a/api/src/shared/infrastructure/utils/logger.js b/api/src/shared/infrastructure/utils/logger.js index 5a905afe3281..335b5348dff4 100644 --- a/api/src/shared/infrastructure/utils/logger.js +++ b/api/src/shared/infrastructure/utils/logger.js @@ -1,3 +1,4 @@ +import { logs, SeverityNumber } from '@opentelemetry/api-logs'; import isEmpty from 'lodash/isEmpty.js'; import omit from 'lodash/omit.js'; import pino from 'pino'; @@ -30,9 +31,58 @@ export const loggerPino = pino( prettyPrint, ); +const OTEL_SEVERITY_NUMBER_BY_LEVEL = { + trace: SeverityNumber.TRACE, + debug: SeverityNumber.DEBUG, + info: SeverityNumber.INFO, + warn: SeverityNumber.WARN, + error: SeverityNumber.ERROR, + fatal: SeverityNumber.FATAL, +}; + +function renderMergingObjectForOtelAttributes(mergingObject) { + if (mergingObject instanceof Error) { + return pino.stdSerializers.err(mergingObject); + } + return Object.fromEntries( + Object.entries(mergingObject) + .map(([key, value]) => { + if (value instanceof Error) { + const errorObject = pino.stdSerializers.err(value); + return Object.entries(errorObject).map(([errorKey, errorValue]) => { + return [`error.${errorKey}`, errorValue]; + }); + } + return [[key, value]]; + }) + .flat(), + ); +} + +function emitOtelLogRecord(context, mergingObject, message, extraBindings) { + const severityNumber = OTEL_SEVERITY_NUMBER_BY_LEVEL[context]; + if (!severityNumber) return; + + // No-op unless OpenTelemetry has been initialized (see initialize-open-telemetry.js), same as the tracing API. + const otelLogger = logs.getLogger('pix-api-logger'); + + const isMergingObjectAMessage = typeof mergingObject === 'string'; + otelLogger.emit({ + severityNumber, + severityText: context, + body: isMergingObjectAMessage ? mergingObject : message, + attributes: { + ...getCorrelationInfo(), + ...extraBindings, + ...(isMergingObjectAMessage ? undefined : renderMergingObjectForOtelAttributes(mergingObject)), + }, + }); +} + function buildLogWrapper(context, mergingObject, message, extraBindings = {}, extraOptions = undefined) { const loggerChild = loggerPino.child({ ...getCorrelationInfo(), ...extraBindings }, extraOptions); loggerChild[context](mergingObject, message); + emitOtelLogRecord(context, mergingObject, message, extraBindings); } export const logger = { diff --git a/api/tests/shared/unit/infrastructure/utils/logger_otel_test.js b/api/tests/shared/unit/infrastructure/utils/logger_otel_test.js new file mode 100644 index 000000000000..bfbc3205681d --- /dev/null +++ b/api/tests/shared/unit/infrastructure/utils/logger_otel_test.js @@ -0,0 +1,95 @@ +import { logs, SeverityNumber } from '@opentelemetry/api-logs'; +import sinon from 'sinon'; + +import { executeInContext, EXECUTORS } from '../../../../../src/shared/infrastructure/execution-context-manager.js'; +import { child, logger } from '../../../../../src/shared/infrastructure/utils/logger.js'; +import { expect } from '../../../../test-helper.js'; + +describe('Unit | Infrastructure | Utils | logger | OpenTelemetry', function () { + let emitStub; + + beforeEach(function () { + emitStub = sinon.stub(); + sinon.stub(logs, 'getLogger').returns({ emit: emitStub }); + }); + + it('emits an OpenTelemetry log record for each log level', function () { + const levelToSeverity = { + trace: SeverityNumber.TRACE, + debug: SeverityNumber.DEBUG, + info: SeverityNumber.INFO, + warn: SeverityNumber.WARN, + error: SeverityNumber.ERROR, + fatal: SeverityNumber.FATAL, + }; + + for (const [level, severityNumber] of Object.entries(levelToSeverity)) { + logger[level]({ foo: 'bar' }, `${level} message`); + + expect(logs.getLogger).to.have.been.calledWith('pix-api-logger'); + expect(emitStub).to.have.been.calledWithMatch({ + severityNumber, + severityText: level, + body: `${level} message`, + attributes: sinon.match({ foo: 'bar' }), + }); + } + }); + + it('does not emit a log record for the silent level', function () { + logger.silent({ foo: 'bar' }, 'should not be emitted'); + + expect(emitStub).to.not.have.been.called; + }); + + it('uses the single string argument as the body when no merging object is provided', function () { + logger.info('a lone message'); + + expect(emitStub).to.have.been.calledWithMatch({ + body: 'a lone message', + }); + const [logRecord] = emitStub.firstCall.args; + expect(logRecord.attributes).to.not.have.property('0'); + }); + + it('includes the correlation info (request_id, user_id, scriptId, jobId) as attributes', function () { + executeInContext( + { request_id: 'request-1', user_id: 'user-1', scriptId: 'script-1', jobId: 'job-1' }, + () => logger.info({}, 'correlated message'), + EXECUTORS.SCRIPT, + ); + + expect(emitStub).to.have.been.calledWithMatch({ + attributes: sinon.match({ + request_id: 'request-1', + user_id: 'user-1', + scriptId: 'script-1', + jobId: 'job-1', + }), + }); + }); + + it('merges the child() bindings into the emitted attributes', function () { + const sectionLogger = child('my-section', { section: 'my-section' }); + + sectionLogger.warn({ detail: 'oops' }, 'section warning'); + + expect(emitStub).to.have.been.calledWithMatch({ + severityNumber: SeverityNumber.WARN, + severityText: 'warn', + body: 'section warning', + attributes: sinon.match({ section: 'my-section', detail: 'oops' }), + }); + }); + + it('serializes without an error given Error objects', function () { + logger.error({ error: new Error('Oups') }, 'Huston, we got a problem'); + + expect(emitStub).to.have.been.calledWithMatch({ + severityNumber: SeverityNumber.ERROR, + severityText: 'error', + body: 'Huston, we got a problem', + attributes: sinon.match({ 'error.type': 'Error', 'error.message': 'Oups', 'error.stack': sinon.match.string }), + }); + }); +});