fix(winston-transport, instrumentation-winston): get the correct severityText and severityNumber with winston.format.colorize() is used (#2956)

Closes: #2952
Co-authored-by: Hector Hernandez <[email protected]>

Author: trentm

packages/instrumentation-winston/package.json

@@ -10,10 +10,7 @@
     "directory": "packages/instrumentation-winston"
   },
   "scripts": {
-    "test": "npm run test-v1-v2 && npm run test-v3 && nyc merge .nyc_output ./coverage/coverage-final.json",
-    "test-v1-v2": "tav winston 2.4.7 npm run test-run",
-    "test-v3": "npm run test-run",
-    "test-run": "nyc --no-clean mocha 'test/**/*.test.ts'",
+    "test": "nyc mocha 'test/**/*.test.ts'",
     "test-all-versions": "tav",
     "tdd": "npm run test-run -- --watch-extensions ts --watch",
     "clean": "rimraf build/*",

packages/instrumentation-winston/test/winston.test.ts

@@ -61,7 +61,11 @@ describe('WinstonInstrumentation', () => {
     cli,
   }
 
-  function initLogger(levelsType?: LevelsType) {
+  /**
+   * Set `logger` to a new Winston logger instance with the given
+   * configuration, and setup with `writeSpy` to spy on emitted logs.
+   */
+  function initLogger(levelsType?: LevelsType, formatType?: string) {
     const winston = require('winston');
 
     let levels = winston.config.npm.levels;
@@ -71,6 +75,19 @@ describe('WinstonInstrumentation', () => {
       levels = winston.config.cli.levels;
     }
 
+    let format;
+    switch (formatType) {
+      case 'colorize':
+        format = winston.format.colorize();
+        break;
+      case 'none':
+      case undefined:
+        format = undefined;
+        break;
+      default:
+        throw new Error(`unknown formatType: "${formatType}"`);
+    }
+
     const stream = new Writable();
     stream._write = () => {};
     writeSpy = sinon.spy(stream, 'write');
@@ -80,6 +97,7 @@ describe('WinstonInstrumentation', () => {
       logger = winston.createLogger({
         level: 'debug',
         levels: levels,
+        format,
         transports: [
           new winston.transports.Stream({
             stream,
@@ -91,6 +109,7 @@ describe('WinstonInstrumentation', () => {
       isWinston2 = true;
       logger = new winston.Logger({
         levels: levels,
+        format,
         transports: [
           new winston.transports.File({
             stream,
@@ -236,6 +255,32 @@ describe('WinstonInstrumentation', () => {
       }
     });
 
+    it('emit LogRecord with correct severity* when colorize() formatter is used', () => {
+      if (!isWinston2) {
+        instrumentation.setConfig({
+          disableLogSending: false,
+        });
+        initLogger(LevelsType.npm, 'colorize');
+
+        logger.log('debug', kMessage);
+        logger.log('info', kMessage);
+        logger.log('warn', kMessage);
+        const logRecords = memoryLogExporter.getFinishedLogRecords();
+        assert.strictEqual(logRecords.length, 3);
+        assert.strictEqual(logRecords[0].severityText, 'debug');
+        assert.strictEqual(logRecords[0].severityNumber, 5);
+        assert.strictEqual(logRecords[0].body, kMessage);
+        assert.strictEqual(logRecords[1].severityText, 'info');
+        assert.strictEqual(logRecords[1].severityNumber, 9);
+        assert.strictEqual(logRecords[1].body, kMessage);
+        assert.strictEqual(logRecords[2].severityText, 'warn');
+        assert.strictEqual(logRecords[2].severityNumber, 13);
+        assert.strictEqual(logRecords[2].body, kMessage);
+
+        initLogger();
+      }
+    });
+
     it('do not emit log record if @opentelemetry/winston-transport load fails', () => {
       const module = require('module');
       const originalRequire = module.prototype.require;

packages/winston-transport/src/utils.ts

@@ -60,19 +60,23 @@ function getSeverityNumber(level: string): SeverityNumber | undefined {
 }
 
 export function emitLogRecord(
-  record: Record<string, any>,
+  record: Record<string | symbol, any>,
   logger: Logger
 ): void {
   const { message, level, ...splat } = record;
   const attributes: LogAttributes = {};
+  // Ensures the log level is read from a symbol property, avoiding any
+  // accidental inclusion of ANSI color codes that may be present in the string
+  // property.
+  const levelSym = record[Symbol.for('level')];
   for (const key in splat) {
     if (Object.prototype.hasOwnProperty.call(splat, key)) {
       attributes[key] = splat[key];
     }
   }
   const logRecord: LogRecord = {
-    severityNumber: getSeverityNumber(level),
-    severityText: level,
+    severityNumber: getSeverityNumber(levelSym),
+    severityText: levelSym,
     body: message,
     attributes: attributes,
   };

packages/winston-transport/test/openTelemetryTransport.test.ts

@@ -74,13 +74,18 @@ describe('OpenTelemetryTransportV3', () => {
     it('npm levels', () => {
       const callback = () => {};
       const transport = new OpenTelemetryTransportV3();
-      transport.log({ message: kMessage, level: 'error' }, callback);
-      transport.log({ message: kMessage, level: 'warn' }, callback);
-      transport.log({ message: kMessage, level: 'info' }, callback);
-      transport.log({ message: kMessage, level: 'http' }, callback);
-      transport.log({ message: kMessage, level: 'verbose' }, callback);
-      transport.log({ message: kMessage, level: 'debug' }, callback);
-      transport.log({ message: kMessage, level: 'silly' }, callback);
+      const sym = Symbol.for('level');
+      for (const level of [
+        'error',
+        'warn',
+        'info',
+        'http',
+        'verbose',
+        'debug',
+        'silly',
+      ]) {
+        transport.log({ message: kMessage, level, [sym]: level }, callback);
+      }
       const logRecords = memoryLogExporter.getFinishedLogRecords();
       assert.strictEqual(logRecords.length, 7);
       assert.strictEqual(logRecords[0].severityNumber, SeverityNumber.ERROR);
@@ -95,16 +100,21 @@ describe('OpenTelemetryTransportV3', () => {
     it('cli levels', () => {
       const callback = () => {};
       const transport = new OpenTelemetryTransportV3();
-      transport.log({ message: kMessage, level: 'error' }, callback);
-      transport.log({ message: kMessage, level: 'warn' }, callback);
-      transport.log({ message: kMessage, level: 'help' }, callback);
-      transport.log({ message: kMessage, level: 'data' }, callback);
-      transport.log({ message: kMessage, level: 'info' }, callback);
-      transport.log({ message: kMessage, level: 'debug' }, callback);
-      transport.log({ message: kMessage, level: 'verbose' }, callback);
-      transport.log({ message: kMessage, level: 'prompt' }, callback);
-      transport.log({ message: kMessage, level: 'input' }, callback);
-      transport.log({ message: kMessage, level: 'silly' }, callback);
+      const sym = Symbol.for('level');
+      for (const level of [
+        'error',
+        'warn',
+        'help',
+        'data',
+        'info',
+        'debug',
+        'verbose',
+        'prompt',
+        'input',
+        'silly',
+      ]) {
+        transport.log({ message: kMessage, level, [sym]: level }, callback);
+      }
       const logRecords = memoryLogExporter.getFinishedLogRecords();
       assert.strictEqual(logRecords.length, 10);
       assert.strictEqual(logRecords[0].severityNumber, SeverityNumber.ERROR);
@@ -122,14 +132,19 @@ describe('OpenTelemetryTransportV3', () => {
     it('syslog levels', () => {
       const callback = () => {};
       const transport = new OpenTelemetryTransportV3();
-      transport.log({ message: kMessage, level: 'emerg' }, callback);
-      transport.log({ message: kMessage, level: 'alert' }, callback);
-      transport.log({ message: kMessage, level: 'crit' }, callback);
-      transport.log({ message: kMessage, level: 'error' }, callback);
-      transport.log({ message: kMessage, level: 'warning' }, callback);
-      transport.log({ message: kMessage, level: 'notice' }, callback);
-      transport.log({ message: kMessage, level: 'info' }, callback);
-      transport.log({ message: kMessage, level: 'debug' }, callback);
+      const sym = Symbol.for('level');
+      for (const level of [
+        'emerg',
+        'alert',
+        'crit',
+        'error',
+        'warning',
+        'notice',
+        'info',
+        'debug',
+      ]) {
+        transport.log({ message: kMessage, level, [sym]: level }, callback);
+      }
       const logRecords = memoryLogExporter.getFinishedLogRecords();
       assert.strictEqual(logRecords.length, 8);
       assert.strictEqual(logRecords[0].severityNumber, SeverityNumber.FATAL3);