fix(instrumentation-pino): log-sending was losing records when the level was reduced (open-telemetry#2699)

Before this fix, if a Pino logger level was reduced (e.g. from 'info' to 'debug'),
then log.debug('msg') would *not* work. The same thing would happen if a child
logger was created at a lower-level than its parent.

This issue was that PinoInstrumentation is internally using a pino multistream
(https://getpino.io/#/docs/api?id=pino-multistream) and statically setting
the level of those streams to the current Logger level. If the logger level
was set lower, the multistream levels would end up filtering records
at that original higher level. The fix is to set the stream levels to
0 to never filter out records.

Closes: open-telemetry#2696

Author: trentm

plugins/node/opentelemetry-instrumentation-pino/src/instrumentation.ts

@@ -109,8 +109,9 @@ export class PinoInstrumentation extends InstrumentationBase<PinoInstrumentation
             const origStream = logger[moduleExports.symbols.streamSym];
             logger[moduleExports.symbols.streamSym] = moduleExports.multistream(
               [
-                { level: logger.level, stream: origStream },
-                { level: logger.level, stream: otelStream },
+                // Use level `0` to never not log a record given to the stream.
+                { level: 0, stream: origStream },
+                { level: 0, stream: otelStream },
               ],
               { levels: logger.levels.values }
             );

plugins/node/opentelemetry-instrumentation-pino/test/pino.test.ts

@@ -473,6 +473,49 @@ describe('PinoInstrumentation', () => {
       });
     });
 
+    it('emits log records to a lower level after level change', () => {
+      const logRecords = memExporter.getFinishedLogRecords();
+
+      logger.debug('first msg at debug');
+      logger.trace('first msg at trace'); // Should *not* see this.
+
+      logger.level = 'trace';
+      logger.debug('second msg at debug');
+      logger.trace('second msg at trace'); // *Should* see this.
+
+      assert.strictEqual(logRecords.length, 3);
+      assert.strictEqual(logRecords[0].severityNumber, SeverityNumber.DEBUG);
+      assert.strictEqual(logRecords[0].severityText, 'debug');
+      assert.strictEqual(logRecords[0].body, 'first msg at debug');
+      assert.strictEqual(logRecords[1].severityNumber, SeverityNumber.DEBUG);
+      assert.strictEqual(logRecords[1].severityText, 'debug');
+      assert.strictEqual(logRecords[1].body, 'second msg at debug');
+      assert.strictEqual(logRecords[2].severityNumber, SeverityNumber.TRACE);
+      assert.strictEqual(logRecords[2].severityText, 'trace');
+      assert.strictEqual(logRecords[2].body, 'second msg at trace');
+    });
+
+    it('emits log records from child logger at lower level', () => {
+      const logRecords = memExporter.getFinishedLogRecords();
+
+      const child = logger.child({ childField: 42 }, { level: 'trace' });
+
+      logger.debug('logger at debug level');
+      logger.trace('logger at trace level'); // Should *not* see this one.
+      child.debug('child at debug level');
+      child.trace('child at trace level'); // *Should* see this one.
+      assert.strictEqual(logRecords.length, 3);
+      assert.strictEqual(logRecords[0].severityNumber, SeverityNumber.DEBUG);
+      assert.strictEqual(logRecords[0].severityText, 'debug');
+      assert.strictEqual(logRecords[0].body, 'logger at debug level');
+      assert.strictEqual(logRecords[1].severityNumber, SeverityNumber.DEBUG);
+      assert.strictEqual(logRecords[1].severityText, 'debug');
+      assert.strictEqual(logRecords[1].body, 'child at debug level');
+      assert.strictEqual(logRecords[2].severityNumber, SeverityNumber.TRACE);
+      assert.strictEqual(logRecords[2].severityText, 'trace');
+      assert.strictEqual(logRecords[2].body, 'child at trace level');
+    });
+
     it('does not emit to the Logs SDK if disableLogSending=true', () => {
       instrumentation.setConfig({ disableLogSending: true });