Pino instrumentation is not sending log message to the logHook method

[gopinathr143]

What version of OpenTelemetry are you using?

    "@opentelemetry/instrumentation-pino": "0.44.0",

What version of Node are you using?

v20.11.1

What did you do?

I am adding pino log messages to the my span using logHook of pino instrumentation. I tried with winston instrumentation. Log messages are adding to the span and able to see it in the jaager UI.

What did you expect to see?

I want log message should be there part of record parameter as like to winston. So I can add it in the span.

What did you see instead?

I don't see log message. But I see only traceId, spanId and trace flags.

Additional context

I am using jaeger all in one collector to collect the traces from my service. I am using GRPC OLTP Trace Exporter to export the traces. I have used pino logger for logging and registered pino instrumentation for automatic log correlation with span Id, trace ID.

tracing.js

const { BatchSpanProcessor, AlwaysOnSampler} = require("@opentelemetry/sdk-trace-base");
const { NodeTracerProvider } = require("@opentelemetry/sdk-trace-node");
const { Resource } = require("@opentelemetry/resources");
const {
  SEMRESATTRS_SERVICE_NAME,
} = require("@opentelemetry/semantic-conventions");
const { diag, DiagConsoleLogger, DiagLogLevel } = require("@opentelemetry/api");
const { HttpInstrumentation } = require("@opentelemetry/instrumentation-http");
const { registerInstrumentations } = require("@opentelemetry/instrumentation");
const {
  OTLPTraceExporter,
} = require("@opentelemetry/exporter-trace-otlp-grpc");
const {
  B3Propagator,
  B3InjectEncoding,
} = require("@opentelemetry/propagator-b3");
const {
  ExpressInstrumentation
} = require('@opentelemetry/instrumentation-express');
const { PinoInstrumentation } = require('@opentelemetry/instrumentation-pino');

module.exports = {
  initTracing: (config) => {
    if (config?.tracing?.enableDebug) {
      diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.ALL);
    }
    const exporter = new OTLPTraceExporter(config.tracing);

    const provider = new NodeTracerProvider({
      sampler: new AlwaysOnSampler(),
      resource: new Resource({
        [SEMRESATTRS_SERVICE_NAME]: config.service_name,
      }),
    });
    provider.addSpanProcessor(new BatchSpanProcessor(exporter, config?.batchSpanProcessorConfig));
    provider.register({
      propagator: new B3Propagator({
        injectEncoding: B3InjectEncoding.MULTI_HEADER,
      }),
    });

    registerInstrumentations({
      instrumentations: [
        new ExpressInstrumentation(),
        new HttpInstrumentation({
          ignoreIncomingRequestHook: function (request) {
            if (config.tracing.urls_to_be_skipped.includes(request.url)) {
              return true;
            }
          },
          applyCustomAttributesOnSpan: function (span, request, response) {
            span.updateName(request.path);
          },
          ignoreOutgoingRequestHook: () => true,
        }),
        new PinoInstrumentation(
            {
              enabled: true,
              logHook: (span, record) => {
                span.addEvent("log", record);
              },
            }
        ),
      ],
      tracerProvider: provider,
    });

    return provider;
  },
};

[trentm]

tl;dr: instrumentation-pino is working as designed. Though it isn't clear in the documentation, the record in logHook(span, record) was never designed to include the Pino log message. I'll explain more below.

repro

I made the following change to your tracing.js to make it easier to debug/see what is going on:

--- tracing.js.orig	2024-12-11 12:44:45
+++ tracing.js	2024-12-11 13:29:28
@@ -1,4 +1,4 @@
-const { BatchSpanProcessor, AlwaysOnSampler} = require("@opentelemetry/sdk-trace-base");
+const { SimpleSpanProcessor, BatchSpanProcessor, AlwaysOnSampler, ConsoleSpanExporter} = require("@opentelemetry/sdk-trace-base");
 const { NodeTracerProvider } = require("@opentelemetry/sdk-trace-node");
 const { Resource } = require("@opentelemetry/resources");
 const {
@@ -24,7 +24,7 @@
     if (config?.tracing?.enableDebug) {
       diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.ALL);
     }
-    const exporter = new OTLPTraceExporter(config.tracing);
+    const exporter = new ConsoleSpanExporter();

     const provider = new NodeTracerProvider({
       sampler: new AlwaysOnSampler(),
@@ -32,7 +32,7 @@
         [SEMRESATTRS_SERVICE_NAME]: config.service_name,
       }),
     });
-    provider.addSpanProcessor(new BatchSpanProcessor(exporter, config?.batchSpanProcessorConfig));
+    provider.addSpanProcessor(new SimpleSpanProcessor(exporter));
     provider.register({
       propagator: new B3Propagator({
         injectEncoding: B3InjectEncoding.MULTI_HEADER,
@@ -57,6 +57,7 @@
             {
               enabled: true,
               logHook: (span, record) => {
+                console.log('XXX logHook called with record=', record);
                 span.addEvent("log", record);
               },
             }

Then I used this main.js to use it:

const {initTracing} = require('./tracing');
initTracing({
    tracing: {}
});

const {trace} = require('@opentelemetry/api');
const pino = require('pino');
const tracer = trace.getTracer('example');

const log = pino();
tracer.startActiveSpan('manual-span', span => {
    log.info('hi')
    span.end();
});

For completeness, here is my package.json:

{
  "name": "asdf.20241211t084855",
  "version": "1.0.0",
  "main": "index.js",
  "dependencies": {
    "@opentelemetry/api": "^1.9.0",
    "@opentelemetry/exporter-trace-otlp-grpc": "^0.56.0",
    "@opentelemetry/instrumentation": "^0.56.0",
    "@opentelemetry/instrumentation-express": "^0.46.0",
    "@opentelemetry/instrumentation-http": "^0.56.0",
    "@opentelemetry/instrumentation-pino": "^0.45.0",
    "@opentelemetry/propagator-b3": "^1.29.0",
    "@opentelemetry/resources": "^1.29.0",
    "@opentelemetry/sdk-trace-base": "^1.29.0",
    "@opentelemetry/sdk-trace-node": "^1.29.0",
    "@opentelemetry/semantic-conventions": "^1.28.0",
    "pino": "^9.5.0"
  }
}

When I run that I see:

% node main.js
XXX logHook called with record= {
  trace_id: '035f1a614bec2a89d2f5f5342475897a',
  span_id: '3fcf38c90c1cb36e',
  trace_flags: '01'
}
{"level":30,"time":1733952890974,"pid":90371,"hostname":"peach.local","trace_id":"035f1a614bec2a89d2f5f5342475897a","span_id":"3fcf38c90c1cb36e","trace_flags":"01","msg":"hi"}
{
  resource: {
    attributes: {
      'service.name': undefined,
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.29.0'
    }
  },
  instrumentationScope: { name: 'example', version: undefined, schemaUrl: undefined },
  traceId: '035f1a614bec2a89d2f5f5342475897a',
  parentId: undefined,
  traceState: undefined,
  name: 'manual-span',
  id: '3fcf38c90c1cb36e',
  kind: 0,
  timestamp: 1733952890974000,
  duration: 1847.834,
  attributes: {},
  status: { code: 0 },
  events: [
    {
      name: 'log',
      attributes: {
        trace_id: '035f1a614bec2a89d2f5f5342475897a',
        span_id: '3fcf38c90c1cb36e',
        trace_flags: '01'
      },
      time: [ 1733952890, 975422042 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}

As you said, the log message is not sent to the logHook:

XXX logHook called with record= {
  trace_id: '035f1a614bec2a89d2f5f5342475897a',
  span_id: '3fcf38c90c1cb36e',
  trace_flags: '01'
}

Going back to the original implementation of instrumentation-pino, the logHook() function was only ever passed a "record" of fields used for trace-correlation:
https://github.com/open-telemetry/opentelemetry-js-contrib/pull/432/files#diff-660728f57a3c2b22336bc39c10f17f768ce60fc9d3e706f7a648e61dc0ebf35bR140-R146

The original intent of the logHook was to be an "Optional hook to insert additional context to log object."
I.e. it was (and is) a way to provide additional fields that will be added to the log record.

why is the log "message" there with instrumentation-winston?

instrumentation-winston was created by the same author, and the intent of the logHook() was the same.
However, because of how the Winston logging pipeline internals work it was convenient to use the Winston info object, rather than using a new record object with the trace-context fields. The "info" object is a Winston object that holds both the additional fields for a log record and the log message.

XXX logHook called with record=  {
  message: 'hi',
  level: 'info',
  trace_id: '93db43c49c0f094b2bc2d2489203ce4b',
  span_id: 'db85c3c5aa5c264c',
  trace_flags: '01',
  [Symbol(level)]: 'info'
}

why is it called "record" then?

So why does logHook(span, record) use the term "record" then?
At the time this was implemented, I don't think OpenTelemetry has a logs signal yet, which defines a LogRecord type.
I think the term "record" here is part of the cause of confusion here. Perhaps a name like "fields" or "recordFields" would be more accurate.

what could be done here?

Getting access to the log message in the logHook function, or some other configurable hook, is effectively a feature request.

Currently the logHook hook in instrumentation-pino is using the pinomixin functionality which does not provide access to the message, so I'm not sure how simple or difficult it would be to provide this functionality.

Have you considered using the OpenTelemetry Logs signal and sending Pino log records via OTLP, rather than adding the log messages as Span Events? To do that you'd want a change to tracing.js something like this:

% diff -u tracing.js tracing-and-logs.js
--- tracing.js	2024-12-11 13:29:28
+++ tracing-and-logs.js	2024-12-11 14:13:54
@@ -19,6 +19,9 @@
 } = require("@opentelemetry/instrumentation-express");
 const { PinoInstrumentation } = require("@opentelemetry/instrumentation-pino");

+const { ConsoleLogRecordExporter, SimpleLogRecordProcessor, LoggerProvider } = require("@opentelemetry/sdk-logs");
+const { logs } = require("@opentelemetry/api-logs");
+
 module.exports = {
   initTracing: (config) => {
     if (config?.tracing?.enableDebug) {
@@ -39,6 +42,14 @@
       }),
     });

+    const loggerProvider = new LoggerProvider({
+      resource: new Resource({
+        [SEMRESATTRS_SERVICE_NAME]: config.service_name,
+      })
+    });
+    loggerProvider.addLogRecordProcessor(new SimpleLogRecordProcessor(new ConsoleLogRecordExporter()));
+    logs.setGlobalLoggerProvider(loggerProvider);
+
     registerInstrumentations({
       instrumentations: [
         new ExpressInstrumentation(),
@@ -56,10 +67,6 @@
         new PinoInstrumentation(
             {
               enabled: true,
-              logHook: (span, record) => {
-                console.log('XXX logHook called with record=', record);
-                span.addEvent("log", record);
-              },
             }
         ),
       ],

Then re-running main:

% node main.js
{
  resource: {
    attributes: {
      'service.name': undefined,
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.29.0'
    }
  },
  instrumentationScope: {
    name: '@opentelemetry/instrumentation-pino',
    version: '0.45.0',
    schemaUrl: undefined
  },
  timestamp: 1733955335837000,
  traceId: '55013ede26908c0e79d992141dac5485',
  spanId: '4ecf0d1274ca0470',
  traceFlags: 1,
  severityText: 'info',
  severityNumber: 9,
  body: 'hi',
  attributes: {}
}
{"level":30,"time":1733955335837,"pid":91340,"hostname":"peach.local","trace_id":"55013ede26908c0e79d992141dac5485","span_id":"4ecf0d1274ca0470","trace_flags":"01","msg":"hi"}
{
  resource: {
    attributes: {
      'service.name': undefined,
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.29.0'
    }
  },
  instrumentationScope: { name: 'example', version: undefined, schemaUrl: undefined },
  traceId: '55013ede26908c0e79d992141dac5485',
  parentId: undefined,
  traceState: undefined,
  name: 'manual-span',
  id: '4ecf0d1274ca0470',
  kind: 0,
  timestamp: 1733955335837000,
  duration: 2046.458,
  attributes: {},
  status: { code: 0 },
  events: [],
  links: []
}

You can see that OpenTelemetry is emitting the LogRecord and separately the Span. The OpenTelemetry LogRecord has traceId and spanId to correlate with the span.

The main question is whether your current telemetry backend supports OTel Logs well or at all.