Log injection doesn't seem to be working with pino

[Ugikie]

I have 2 separate projects, both using the exact same code for dd-trace and pino. One of the projects, shows the dd trace information in the output logs, while the other project does not. I am pretty new to both dd-trace and pino, but I cannot figure out why the dd object is not showing up in the logs.

dd-trace: v2.4.2 pino: v8.1.0

./logger.ts

import tracer from 'dd-trace'
import { pino } from 'pino'

tracer.init({ startupLogs: true, logInjection: true }) // initialized in a different file to avoid hoisting.

export const logger = pino()

./index.ts

import { logger } from './logger'

logger.error({ err: { message: 'test' } })

Output:

{"level":50,"time":1657932466511,"pid":32232,"hostname":"DESKTOP-OPPS0B5","err":{"message":"test"},"msg":"test"}

Desired Output:

{"level":50,"time":1657932882211,"pid":54284,"hostname":"DESKTOP-OPPS0B5","dd":{"trace_id":"2199711714951426111","span_id":"2195427521297530161","service":"test-api","version":"0.0.0"},"err":{"message":"test"},"msg":"test"}

Is there something I need to do in order for this information to be properly added onto the log message?

[bengl]

@Ugikie Hello!

Our log injection will only actually inject when there's an active trace. At application startup, there ins't one active. You can test if there's an active trace at the point of logging by checking whether tracer.scope().active() returns a span. If it returns null, then you don't have an active span or trace, and so log injection won't happen.

[jstayton]

I'm running into the same thing with pino v8.1.0 and dd-trace v2.10.0. Whether I log something within a Fastify request (automatically instrumented) or a background job (manually instrumented), they don't include a trace_id.

I'm importing the tracer before anything else, including pino. Is there a way to troubleshoot?

[Ugikie]

@Ugikie Hello!

Our log injection will only actually inject when there's an active trace. At application startup, there ins't one active. You can test if there's an active trace at the point of logging by checking whether tracer.scope().active() returns a span. If it returns null, then you don't have an active span or trace, and so log injection won't happen.

Thanks for the info, that makes total sense actually. But if a trace is not active on app startup, then when does the trace become active? Does it just take a few seconds? Or is there some condition that is met or something that needs to be done in order to "activate" the trace?

Just trying to ensure all of my logs are logged with a trace_id

[rochdev]

But if a trace is not active on app startup, then when does the trace become active?

There is a trace per request, so basically a trace becomes active when a request comes in until the request has been handled. Multiple simultaneous requests would each have their own traces. When a trace is active and an instrumented logger adds a log entry, the tracing context is added to the entry. If a trace is not available then injection won't happen but that's expected since there is no trace to inject.

From your original snippet, it looks like the tracer is initialized after pino has been imported. This can result in unexpected behaviour, especially with recent changes that we made to the plugin system, but it was never supported in the first place although it used to work sometimes. The tracer always needs to be initialized before any instrumented module is imported to work properly. You can find more information in the setup guide.

It's also possible there is a bug, but generally speaking the above are the 2 main reasons for log injection not to work so I want to make sure these are not the issue first.

[Ugikie]

But if a trace is not active on app startup, then when does the trace become active?

There is a trace per request, so basically a trace becomes active when a request comes in until the request has been handled. Multiple simultaneous requests would each have their own traces. When a trace is active and an instrumented logger adds a log entry, the tracing context is added to the entry. If a trace is not available then injection won't happen but that's expected since there is no trace to inject.

From your original snippet, it looks like the tracer is initialized after pino has been imported. This can result in unexpected behaviour, especially with recent changes that we made to the plugin system, but it was never supported in the first place although it used to work sometimes. The tracer always needs to be initialized before any instrumented module is imported to work properly. You can find more information in the setup guide.

It's also possible there is a bug, but generally speaking the above are the 2 main reasons for log injection not to work so I want to make sure these are not the issue first.

Okay that makes more sense - so it seems to be based on when a request comes in.. Well, what if I am not dealing with requests, and instead just want to log some information from my node script, but include a trace_id? For example, in my original issue, I mentioned I have 2 projects using the same logging code.. The project that correctly logs with the dd trace information, is an api, using koa, and you are correct in that when I make a request to that api, the logs that occur in the route handlers properly include the trace information. However, the second project is more like a script (without any routes) and it just polls for incoming messages on an aws sqs queue (again, not request based).

So maybe because the second project is not using koa, and is not taking http requests, it is not activating a trace. If that is the case, how could I still have trace information in my logs if I am not using something like koa?

Also, regarding the order of imports - I have seen this mentioned a lot, and considered it could be the issue, but I do not see any changes in the results when I switch the order of the imports.

I really appreciate both of you helping out with this issue!

[rochdev]

@Ugikie When I said "request" I should have said "operation". For auto-instrumentation that usually means a request, but it can be any operation, including anything that is happening within a script. However, if there is no request active then you would have to manually start a span to surround your operation, which will then give you not only log correlation but also tracing which you wouldn't otherwise have, or if you do it would be incomplete.

For example:

const tracer = require('dd-trace').init()

tracer.trace('some.name', () => {
  // Your script should run here to be completely wrapped in a trace.
  // The span will automatically finish when the function return,
  // or if the return value is a promise when the promise resolves.
  // Any log entry here will have  the trace ID of the `some.name` span.
})

Any asynchronous operations created within the context of the tracer.trace callback will also automatically inherit the scope of the span and be a child of the span, for example the SQS span.

[rochdev]

@jstayton Can you share the entry point of your application? There are cases where even though it seems the tracer is initialized before other imports it's not actually the case, for example with transpilation or when using a wrapper framework like NextJS.

I'm importing the tracer before anything else, including pino. Is there a way to troubleshoot?

It's worth noting that the tracer should be initialized (so tracer.init has already been called) before other modules are imported (so either import or require is called). Even if the tracer is imported first, that still doesn't work if it's initialized later. We're working on improving this so that only the import order is important, but for now the initialization is still the important part. I would start with making sure that this is the case before investigating other possible causes as it's the most common issue.

[Ugikie]

tracer.trace('some.name', () => {
  // Your script should run here to be completely wrapped in a trace.
  // The span will automatically finish when the function return,
  // or if the return value is a promise when the promise resolves.
  // Any log entry here will have  the trace ID of the `some.name` span.
})

Looks like that was it! I guess I was just missing the fact that I needed to handle the instrumentation manually. I was under the impression that as long as I initialized dd-trace, then all of my logs would be associated with some "trace" and have an id. But I am slowly learning how all of this span/trace/scope stuff works and I think I got it now.

Wrapping my code in your snippet, I am now seeing the dd object that I was expecting. Thank you again for helping resolve this! 🙌⭐

[davidcam-nwse]

From your original snippet, it looks like the tracer is initialized after pino has been imported. This can result in unexpected behaviour, especially with recent changes that we made to the plugin system, but it was never supported in the first place although it used to work sometimes. The tracer always needs to be initialized before any instrumented module is imported to work properly. You can find more information in the setup guide.

I was pulling my hair already until I read the paragraph above.

For me this solved all of my issues with log correlation not working despite all the other integrations and settings being correct. So I imported and initialized the tracer, and then imported the Logger (in that order) and log correlation worked as expected. Thanks, @rochdev! 🙂 👍