Dd-trace-js: Log injection stopped working with pino in a recent release

[EricZaporzan]

Describe the bug

When planning an upgrade of dd-trace across our applications, we observed that log injection stopped working with our logger of choice, pino. I have narrowed down the start of the problem to v0.20.2, and I've attached a little script that reproduces the issue.

const pino = require('pino');
const tracer = require('dd-trace');

tracer.init({
    logInjection: true
});

const logger = pino();

tracer.trace('test-trace', () => {
    logger.error('Test message');
});

Output on dd-trace < 0.20.2: {"level":50,"time":1594597807867,"pid":8457,"hostname":"***","dd":{"trace_id":"5976976212417514776","span_id":"5976976212417514776"},"msg":"Test message"}

Output on dd-trace >= 0.20.2 {"level":50,"time":1594598167567,"pid":8569,"hostname":"***","msg":"Test message"}

Environment

• Operation system:

MacOS 10.15.3 (also reproduced on docker linux)

• Node version:

12.x

• Tracer version:

  >= 0.20.2

• Agent version:

Any (does not appear to be an agent issue)

[EricZaporzan]

For good measure, I spot-checked this on a few versions of Pino. I saw the same results on the latest pino release (6.3.2), as well as the latest 5.x release (5.17.0) and 5.0.0

[rochdev]

The tracer must be initialized before instrumented modules, so in this case the above code should look like this instead:

const tracer = require('dd-trace');
const pino = require('pino');

Initializing the tracer after importing instrumented module is not supported so the expected behavior is not defined and may vary between versions.

[EricZaporzan]

@rochdev apologies, and thanks for the reminder. I reconfigured the code to require the tracer first, and we're still seeing the same behaviour:

const tracer = require('dd-trace');

const pino = require('pino');

tracer.init({
    logInjection: true
});

const logger = pino();

tracer.trace('test-trace', () => {
    logger.error('Test message');
});

[rochdev]

Turns out my snippet was incorrect as well as I forgot to also move the initialization, sorry about that.

Correct ordering:

const tracer = require('dd-trace');

tracer.init({
    logInjection: true
});

const pino = require('pino');

[EricZaporzan]

No worries, looks like that's what we're running into, as we initialize the logger very early for startup logging. Thanks for the help!

[jeromemacias]

Sorry for re-open the discution, but how can we set the pino logger as dd-trace logger if we must initialize the tracer before pino logger ?

Here is an example :

const tracer = require('dd-trace');

const pino = require('pino');

const logger = pino();

tracer.init({
    logInjection: true,
    logger
});

tracer.trace('test-trace', () => {
    logger.error('Test message');
});

So the log injection will be broken.
Maybe we cannot do the log injection for the current dd-trace used logger using Pino.

Thanks !

[rochdev]

While not ideal, for now you would have to swap the implementation after the initialization. For example:

const tracer = require('dd-trace');

// each method could be no-op which would swallow the init logs or another temporary implementation like `console`.
const logger = {
  error: () => {},
  warn: () => {},
  info: () => {},
  debug: () => {}
};

tracer.init({
    logInjection: true,
    logger
});

const pino = require('pino');
const realLogger = pino();

logger.error = realLogger.error.bind(realLogger);
logger.warn = realLogger.warn.bind(realLogger);
logger.info = realLogger.info.bind(realLogger);
logger.debug = realLogger.debug.bind(realLogger);

tracer.trace('test-trace', () => {
    logger.error('Test message');
});

I will try to think of an API that would allow to patch modules before initializing the tracer so that this use case is covered.

[fishera123]

While not ideal, for now you would have to swap the implementation after the initialization. For example:

const tracer = require('dd-trace');

// each method could be no-op which would swallow the init logs or another temporary implementation like `console`.
const logger = {
  error: () => {},
  warn: () => {},
  info: () => {},
  debug: () => {}
};

tracer.init({
    logInjection: true,
    logger
});

const pino = require('pino');
const realLogger = pino();

logger.error = realLogger.error.bind(realLogger);
logger.warn = realLogger.warn.bind(realLogger);
logger.info = realLogger.info.bind(realLogger);
logger.debug = realLogger.debug.bind(realLogger);

tracer.trace('test-trace', () => {
    logger.error('Test message');
});

I will try to think of an API that would allow to patch modules before initializing the tracer so that this use case is covered.

is this still the way to go?

[rochdev]

@fishera123 It is indeed still the way to go.

[shellscape]

@rochdev safe to say that this goes a bit beyond non-optimal. Why not move whatever require-time code that's running into a load method or some such? That's a pretty common pattern. Require-time running of required code is quite the anti-pattern!

[rochdev]

@shellscape Can you provide an example? The problem is that the tracer must be loaded before the logger so that it can patch it, but the logger has to be loaded before the tracer so it can be used by the tracer for logging.