Injecting custom tags into logs

[acSpock]

This is more of a how to question than an issue. With logInjection enabled, our fastify/pino app is injecting all logs that has the "dd" object added within every request context

    reqId: "req-1"
    dd: {
      "trace_id": "7309428191517173231",
      "span_id": "7309428191517173231",
      "service": "our-service",
      "version": "development",
      "env": "local"
    }

This is good, but we have a lot of hooks and some of our routes would benefit from injecting additional data further down the request. Does dd-trace support this behavior without having to re-wrap everything in a custom trace?

I'm able to add custom tags like so to an active scope:

 tracer.scope().active()?.addTags({customId: record.Id., additionalData: 'data'})

But it's not clear what's the most pragmatic path forward to add them to each log.

Should I:

1. Override the custom logger functions (info, error, warn, etc) and add the tags there?
2. Create a new span context with tracer.trace and use childOf as the object body to inject the desired data?
3. Some configuration I'm not aware

Any guidance would help find the best solution. Thanks!

[rochdev]

Log injection only augments your existing logs with the tracing context in order to correlate between traces and logs. It's not really meant for injecting arbitrary tags. Any additional properties that should be added to the log entries should be done at the logger level and not at the tracer level.

For example, say you are using Winston as your logger, you could do something like this:

const { format } = require('winston')

const withTags = format((info, opts) => {
  info.customId = record.Id
  info.additionalData = 'data'

  return info;
})

const { createLogger, format, transports } = require('winston')
const { combine } = format

const logger = createLogger({
  format: combine(
    withTags(),
    // your existing format(s)
  ),
  transports: [new transports.Console()]
})

[acSpock]

Thanks @rochdev. We unfortunately do still have a use case for needing to inject logs with a customId either at the top of the execution stack of a new web request or sometimes in the middle of the request at our service layer. So I'm not sure that the approach you mentioned will work since that's done at startup and not during runtime during every request.

Maybe dd-trace isn't the tool for the job but how does dd-trace inject custom logs into pino logger if we wanted to replicate this behavior? I know dd-trace uses async hooks but would need to dig through the source code.

[rochdev]

The formatter executes when log entries are generated, so for your use case I would use an AsyncLocalStorage instance for the request, store the customId on it, and grab it in the formatter.

For example:

const { AsyncLocalStorage } = require('async_hooks')
const express = require('express')
const { createLogger, format, transports } = require('winston')
const { combine, json } = format

const app = express()
const storage = new AsyncLocalStorage()

const withTags = format((info, opts) => {
  const store = storage.getStore()

  info.customId = store.customId
  info.additionalData = 'data'

  return info
})

const logger = createLogger({
  format: combine(
    withTags(),
    json()
  ),
  transports: [new transports.Console()]
})

// this should go before any logging middleware
app.use((req, res, next) => {
  storage.enterWith({})
  next()
})

// some other middleware that gets the customId
app.use((req, res, next) => {
  const store = storage.getStore()

  store.customId = getCustomId()

  next()
})

// the middleware that is logging
app.get('/foo', (req, res) => {
  logger.info('hello')
  res.end()
})

app.listen(3030)

function getCustomId () {
  return 123
}

The same approach can be used for any value you need stored for the request, including for logging and tracing, but really it could be used for anything.

[rochdev]

Just noticed you're using Pino. For Pino I think the equivalent to Winston formatters would be transport pipelines.

[acSpock]

This is the approach I ended up going with. Appreciate the responses @rochdev.

[acSpock]

I want to comment on this thread if anyone comes across this wanting to use Pino that transport pipelines run in a separate worker thread and is outside the context of whatever web request AsyncLocalStorage thread is using. You would either need to create a new local context with AsyncResource and use runInAsyncScope inside your pipeline or you can just use the formatters log property on pino itself and use the AsyncLocalStorage instance you created which is fine for simple systems.