Log injection breaks when upgrading from v0.15.5 to v0.16.2

[reinpold]

Describe the bug
When upgrading dd-trace to v0.16.2 logs do not contain dd (https://github.com/DataDog/dd-trace-js/blob/v0.16.2/packages/dd-trace/src/plugins/util/log.js#L13-L16) block any more.

The issue seems to be in Instrumenter.enable method https://github.com/DataDog/dd-trace-js/blob/v0.16.2/packages/dd-trace/src/instrumenter.js#L39-L52 Namely, plugins do not get auto-instrumented, because this._enabled is set to true after setting and loading the plugins and not before. load method simply returns if this._enabled is false: https://github.com/DataDog/dd-trace-js/blob/v0.16.2/packages/dd-trace/src/instrumenter.js#L98 Moving this._enabled = true to the begging of enable method fixes log injection issue, but might introduce others.

Environment
DD_LOGS_INJECTION=true
DD_TRACE_ANALYTICS_ENABLED=true
DD_RUNTIME_METRICS_ENABLED=true

• Operation system:
  Alpine Linux 3.9.4
• Node version:
  v10.17.0
• Tracer version:
  v0.16.2
• Agent version:
  v6.15.1

[rochdev]

In general it should be fine to move this._enabled = true to the top, but I can't seem to be able to reproduce the issue. I'm thinking it may be related to the ordering of the initialization code. Can you share a snippet of your initialization code for the tracer and the logger?

[reinpold]

When I add console.log('load', meta.name, this._enabled) to the first line of Instrumenter.load then following gets printed to console:

load amqp10 false
load amqplib false
load bluebird false
load bunyan false
load cassandra-driver false
load connect false
load couchbase false
load dns false
load elasticsearch false
load express false
load fastify false
load generic-pool false
load graphql false
load grpc false
load hapi false
load http false
load http2 false
load ioredis false
load knex false
load koa false
load limitd-client false
load memcached false
load mongodb-core false
load mysql false
load mysql2 false
load net false
load paperplane false
load pg false
load pino false
load promise false
load promise-js false
load q false
load redis false
load restify false
load router false
load tedious false
load when false
load winston false
load express true

tracer.ts looks like this:

import * as winston from 'winston';

const logger = winston.createLogger({
  format: winston.format.json(),
  defaultMeta: { service: 'dd-trace' },
  level: 'debug',
  transports: [new winston.transports.Console()],
});

import tracer from 'dd-trace';

tracer.init({
  logger: {
    debug: message => logger.debug(message),
    error: err => {
      if (err) {
        logger.error('Tracing error: ', err);
      }
    },
  },
  trackAsyncScope: true,
});

tracer.use('express', {
  blacklist: ['/healthcheck'],
  headers: ['x-apollo-operation-name', 'user-agent', 'x-amzn-trace-id'],
});

[rochdev]

Ok, I'll look into it. At a minimum I'll move this._enabled = true to the top, but I also want to try and simplify how we load modules. In the meantime, it should be enough to add tracer.use('winston') after init() is called, similar to express.

[reinpold]

Very nice! Thanks for quickly resolving this.