Not able to pass trace_id to pino transport

[Dhruv-Garg79]

I am trying to associate trace with logs, but trace_id field is not getting sent to OTEL collector.

const pinoLogger = pino(
	{
		level: 'debug',
		timestamp: true,
	},
	pino.transport({
		targets: [
			{
				level: 'debug',
				target: 'pino-pretty',
				options: {
					colorize: false,
					ignore: 'pid,hostname,time,trace_id,funcName',
					messageFormat: '{trace_id} {funcName} {msg}',
					sync: false,
				},
			},
			{
				level: 'debug',
				target: 'pino-opentelemetry-transport',
				options: {
					sync: false,
				},
			},
		],
	}),
);

pinoLogger.debug({trace_id: "Asdasdasd", funcName: "Asdasd"}, "message")

• when I tried with traceId field, it was coming in attributes
• when trying with trace_id, it is not coming anywhere in the JSON.

version used - ^0.4.1
node version - v20.12.0

[Vunovati]

Hello @Dhruv-Garg79,

are you using the pino instrumentation for tracing? Here is an example of how to use the transport with context propagation:

https://github.com/Vunovati/pino-opentelemetry-transport/tree/main/examples/trace-context

Do you have some different use case that prevents you from using pino instrumentation? If so, please describe.

[Dhruv-Garg79]

My use case is simple, I don't want to use async hooks, and that's why I am passing these values manually.
so that's why wanted to know, if there's a way to pass this value manually.

I can pass it as attribute or anything else that might be required @Vunovati
I can also pass the trace.context manually to the pinoLogger.debug if needed

[Dhruv-Garg79]

@Vunovati I have explained my use case. is it possible to tell any way around? I just want simply pass these values manually

[Vunovati]

Hello,

Can you explain what's the problem with async hooks?
This is not a use case that I expected so I need more info.

What is the current output of the logs in the collector? Can you add an example?
Can you add an example of what you'd expect as an output?

Thanks

[Dhruv-Garg79]

{
  "body": "response body {\"task_ids\":[],\"rewards\":[]}",
  "id": "2gPw1VGs8jPDuY5HfiZULNAX0Ii",
  "timestamp": "2024-05-17T08:35:29.944Z",
  "attributes": {
    "funcName": "trackEvent"
  },
  "resources": {
    "host.arch": "arm64",
    "host.name": "api-server-7fdd58c787-bkp2d",
    "os.type": "linux",
    "os.version": "5.10.215-203.850.amzn2.aarch64",
    "process.command": "/usr/src/app/node_modules/thread-stream/lib/worker.js",
    "process.command_args": "[\"/usr/local/bin/node\",\"--max-semi-space-size=64\",\"--max-old-space-size=1024\",\"/usr/src/app/node_modules/thread-stream/lib/worker.js\"]",
    "process.executable.name": "node",
    "process.executable.path": "/usr/local/bin/node",
    "process.owner": "root",
    "process.pid": "8",
    "process.runtime.description": "Node.js",
    "process.runtime.name": "nodejs",
    "process.runtime.version": "20.12.2"
  },
  "severity_text": "DEBUG",
  "severity_number": 5,
  "span_id": "",
  "trace_flags": 0,
  "trace_id": ""
}

Hey @Vunovati this is the sample I am getting. I have already added how I am sending logs in the main post. like this:

pinoLogger.debug({trace_id: "Asdasdasd", funcName: "Asdasd"}, "message")

As, you can see the trace_id is coming empty, when I have already passed it.

problem with async hooks is simple, they are big performance killer. up to 50% in many cases.

[Vunovati]

Would it work for you to try passing span_id and trace_flags in addition to trace_id?

We need all three to be there in order to add them to the context:

https://github.com/Vunovati/otlp-logger/blob/b65f91e20590cd6eff50cffa96337a9c09b43c27/lib/otlp-logger.js#L80-L84

[Dhruv-Garg79]

yes, that will work, let me try that. can you tell what exactly is trace_flags?

[Vunovati]

Yes, it is described here: https://www.w3.org/TR/trace-context/#trace-flags

You can put '01' as a value which means sampled:

The sampled flag can be used to ensure that information about requests that were marked for recording by the caller will also be recorded by SaaS service downstream so that the caller can troubleshoot the behavior of every recorded request.
https://www.w3.org/TR/trace-context/#sampled-flag

[Dhruv-Garg79]

Hey I tried, passing same value for both span_id and trace_id and sent 01 for trace_flags, but still I am not getting it on signoz dashboard.

    trace_id: "27757839f1e7eb49f4a4a84407e78c05"
    span_id: "27757839f1e7eb49f4a4a84407e78c05"
    funcName: "identify"
    trace_flags: "01"
[13:04:15.695] DEBUG (57389 on ip-192-168-1-7.ap-south-1.compute.internal): 27757839f1e7eb49f4a4a84407e78c05 identify PUT /api/sdk/identify 200 1380.67 ms

I am getting the funcName value, but not the others related to trace_id and all

[Vunovati]

@Dhruv-Garg79, can you try giving me the output of the tail -f /tmp/test-logs/otlp-logs.log generated by the Opentelemetry collector like described in the trace-context example?

We need to isolate and confirm that this is the issue with this transport and not with signoz. I haven't tried signoz yet.

p.s. You are using the same value for trace_id and span_id. I don't think that's a good idea. If you are not using ready-made instrumentations, you should try to implement a similar mechanism manually. For each span within the same trace, you need to create a unique span_id.

[Dhruv-Garg79]

I am not able to see any file getting generated in this location /tmp/test-logs/otlp-logs.log. But I am sure that these values are getting send because I added 2 targets to the pino - stdout and pino-opentelemetry-transport like this:

const pinoLogger = pino(
	{
		level: 'debug',
		timestamp: true,
	},
	pino.transport({
		targets: [
			{
				level: 'debug',
				target: 'pino-pretty',
				options: {
					colorize: false,
					ignore: 'pid,hostname,time,trace_id,span_id,trace_flags,service,funcName',
					messageFormat: '{trace_id} {funcName} {msg}',
					sync: false,
				},
			},
			{
				level: 'debug',
				target: 'pino-opentelemetry-transport',
				options: {
					sync: false,
				},
			},
		],
	}),
);

And in my terminal, I am getting these values

    trace_id: "09c168552b4e50e6d2538fe1273d8fbc"
    span_id: "09c168552b4e50e6d2538fe1273d8fbc"
    
    funcName: "trackEvent"
    service: "api-server"
    trace_flags: "01"
[14:29:45.722] DEBUG (8019): sent message to kafka topic_events [{"topicName":"topic_events","partition":1,"errorCode":0,"baseOffset":"19","logAppendTime":"-1","logStartOffset":"13"}]

is there some other way to check what exactly is sent by pino-opentelemetry-transport? I tried but wasn't able to figure out yet.

Also I am using these env variables for sending logs

OTEL_EXPORTER_OTLP_LOGS_PROTOCOL=grpc
OTEL_EXPORTER_OTLP_LOGS_ENDPOINT=http://123.123.123.123:4317

I am using NodeTracerProvider from @opentelemetry/sdk-trace-node to get tracer object.

After that, I use below code to create a logger per API request.

			const trace = tracer.startSpan(functionName);
			const traceId = trace.spanContext().traceId;
			const logger = new Logger({
				trace_id: traceId,
				span_id: traceId,
				trace_flags: '01',
				funcName: functionName,
				service:serviceName,
			});

Now, in this, I am getting traceId from spanContext() and I want to only have 1 trace per API request, which maps my traces to logs, so that I can identify relate logs to slow/errored traces.

That's why I had to pass same traceId and spanId. I will try to change it, but don't have idea how to do it properly.

One more thing, it works if I send traceId and spanId but not when I send trace_id and span_id.

[Vunovati]

I am unable to really understand what is going on with your code so can you please help me out?

I see from your env vars that you are sending the traces to some external collector. We could debug much more easily if you sent those to a local collector like in all examples in this repo.

In the examples, we are sending logs to a collector on localhost. I need you to do the same thing so that I can reproduce the potential issue. We need to eliminate the external factors here like your collector on http://123.123.123.123:4317

My suggestion. Remove the env vars OTEL_EXPORTER_OTLP_LOGS_ENDPOINT and OTEL_EXPORTER_OTLP_LOGS_PROTOCOL. This way the transport will use localhost and http as a default.

Then clone this repo and run docker compose up from within the repo. This will run the collector on your machine. This collector will log all the stuff to /tmp/test-logs/otlp-logs.log

[Vunovati]

Here is a working example of what I think you want:

const pino = require('pino')

const transport = pino.transport({
  targets: [
    {
      target: 'pino-opentelemetry-transport',
      options: {
        logRecordProcessorOptions: [
          {
            recordProcessorType: 'simple',
            exporterOptions: { protocol: 'http' }
          },
          {
            recordProcessorType: 'simple',
            exporterOptions: { protocol: 'console' }
          }
        ],
        loggerName: 'test-logger',
        serviceVersion: '1.0.0'
      }
    }
  ]
})

const pinoLogger = pino(
  {
    level: 'debug',
    timestamp: true
  },
  transport
)

let i = 0

setInterval(() => {
  pinoLogger.info(
    {
      trace_id: '2469f8f5d2a271714f2777732593bf70',
      span_id: '10e255d24e7d549a',
      trace_flags: '01',
      funcName: 'Asdasd'
    },
    `message ${i++}`
  )
}, 1000)

It will send the logs to the http collector locally
{ recordProcessorType: 'simple', exporterOptions: { protocol: 'http' } },

and will log what it would be sending to stdout

{ recordProcessorType: 'simple', exporterOptions: { protocol: 'http' } },

Please also note that the values for span_id and the trace_id that we are sending are spec compliant. The trace_id is a 16 byte array, while the span_id is a 8-byte array.

If you send just any string as those values, the traceId and spanId will not be displayed. The values need to be as per spec.

What I can see in your comment above you were sending an 16 byte array as span_id, while it should've been 8

[Dhruv-Garg79]

@Vunovati it worked, thanks for taking time to help me out with this.
The issue was passing same trace_id to span_id as well, I also upgraded to latest version of opentelemetry APIs for node and was able to get spanId in spanContext(), earlier when I had checked there wasn't this field.