v0.10.3 adds a `dd` prop to my postgres query

[SethDavenport]

I updated from dd-trace-js 0.7.2 to 0.10.3 (and turned on the logInjection feature) and suddenly my insert and update postgres queries started failing:

dd is not a column in my table.

Here's the code that results in that query:

class Account {
  // ...
  save = async () => {
    const params = {
      user_id: this.userId,
      start_of_day_buying_power: this.startOfDayBuyingPower.amount,
      start_of_day_available_to_withdraw: this.startOfDayAvailableToWithdraw
        .amount,
      external_account_id: this.externalAccountId,
      custodian_account_number: this.custodianAccountNumber,
      status: this.status,
      last_synced_at: this.lastSyncedAt,
    };

    logger.info(this.ctx, `Account.save(id: ${this.id} -- `, params);
    return await this.ctx
      .db('accounts')
      .where({ id: this.id })
      .update(params);
  };
}

I am not explicitly setting a dd prop on the params object I'm sending to knex.js (our ORM).

The log entry generated from this function is as follows:

Account.save(id: 39988 --  { user_id: 42112,
  start_of_day_buying_power: 394.72,
  start_of_day_available_to_withdraw: 394.72,
  external_account_id: 'non-registered-o-tdmki3',
  custodian_account_number: 'H03968403CAD',
  status: 'open',
  last_synced_at: '2019-04-07T18:28:26.813Z',
  dd:
   { trace_id: '1230130684774463716',
     span_id: '8158257002736448946' } }

It looks like trace injection is adding a dd property to the params object I pass to knex.js; this extra property is causing knex to think I have a column in my table called dd when in fact I don't.

[SethDavenport]

My Data dog init code looks like this:

// @flow
import ddTrace from 'dd-trace';
import { k, PROJECT_ENV } from '../project-env';

export const tracer = ddTrace.init({
  service: `${k.DATADOG_APM_DEFAULT_SERVICE}-${k.APP_ROLE}`,
  enabled: k.DATADOG_APM_ENABLED,
  hostname: k.DATADOG_APM_HOST,
  port: k.DATADOG_APM_PORT,
  debug: k.DATADOG_APM_PORT,
  tags: { env: PROJECT_ENV },
  logInjection: true,
});

Downgrading back to 0.7.2 and removing the new logInjection: true (:cry:) resolves the issue.

[SethDavenport]

Environment:

• node 10.15.3
• koa 2.6.2
• knex 0.16.3
• pg 7.7.1
• winston 2.4.4

[SethDavenport]

I think the issue is here:

https://github.com/DataDog/dd-trace-js/blob/41396ff47ccf234b584e4787e0c1bad01dee81cf/src/plugins/util/log.js#L13

This correlate function appears to be applied to any object passed as an argument to winston.info:

https://github.com/DataDog/dd-trace-js/blob/41396ff47ccf234b584e4787e0c1bad01dee81cf/src/plugins/winston.js#L25

However it mutates the input which as a caller I find unexpected.

Would it make sense to do something like this?

utils/log.js:

'use strict'

const tx = require('./tx')

const log = {
  // Add trace identifiers from the current scope to a log record.
  correlate (tracer, record) {
    const span = tracer.scope().active()

    record = record || {}

    if (span) {
      // Don't mutate the input.
      return Object.assign(
        {},
        record,
        {
          dd: {
            trace_id: span.context().toTraceId(),
            span_id: span.context().toSpanId(),
          },
        });
    }

    return record
  }
}

module.exports = Object.assign({}, tx, log)

[SethDavenport]

Actually looking again, tx.correlate is used in bunch of places and it looks like making it not mutate its input will break a bunch of stuff. Maybe instead we can update winston.js to something like this?

function createWrapLog (tracer, config) {
  return function wrapLog (log) {
    return function logWithTrace (level, msg, meta, callback) {
      const scope = tracer.scope().active()

      if (!scope || arguments.length < 1) return log.apply(this, arguments)

      const correlatedArguments = Array.prototype.slice.call(arguments)
      for (let i = 0, l = correlatedArguments.length; i < l; i++) {
        if (typeof correlatedArguments[i] !== 'object') continue

        tx.correlate(tracer, correlatedArguments[i])

        return log.apply(this, correlatedArguments)
      }

      meta = tx.correlate(tracer)
      callback = arguments[arguments.length - 1]

      const index = typeof callback === 'function'
        ? arguments.length - 1
        : arguments.length

      Array.prototype.splice.call(arguments, index, 0, meta)

      return log.apply(this, arguments)
    }
  }
}

[rochdev]

I think the change you are proposing would make sense in every place where tx.correlate is used. I didn't think about the case where an object that is used outside of logging would be passed to a logger when designing this, but it makes sense that the original object is never altered. I will try to see if this can be done for every logger.