Fix log injection and applied sampling rule bug (#6299)

* fix log injection and sampling rule bug

* instead of deferring sampling decision seperate log injection from sampling

* revert

* address feedback

Author: khanayan123

integration-tests/log_injection.spec.js

@@ -0,0 +1,66 @@
+'use strict'
+
+const { FakeAgent, createSandbox, spawnProc, curlAndAssertMessage, assertObjectContains } = require('./helpers')
+const path = require('path')
+const { USER_KEEP } = require('../ext/priority')
+
+describe('Log Injection', () => {
+  let agent
+  let proc
+  let sandbox
+  let cwd
+  let app
+  let env
+
+  before(async () => {
+    sandbox = await createSandbox(['express', 'winston'])
+    cwd = sandbox.folder
+    app = path.join(cwd, 'log_injection/index.js')
+  })
+
+  after(async () => {
+    await sandbox.remove()
+  })
+
+  beforeEach(async () => {
+    agent = await new FakeAgent().start()
+  })
+
+  describe('log injection with rule based sampling', () => {
+    beforeEach(async () => {
+      agent = await new FakeAgent().start()
+    })
+
+    afterEach(async () => {
+      proc.kill()
+      await agent.stop()
+    })
+
+    it('should correctly apply rule based sampling when log injection is enabled', async () => {
+      env = {
+        AGENT_PORT: agent.port,
+        lOG_INJECTION: 'true'
+      }
+      proc = await spawnProc(app, { cwd, env, execArgv: [] })
+      const url = proc.url + '/sampled'
+      return curlAndAssertMessage(agent, url, ({ headers, payload }) => {
+        // Bug: previously got USER_REJECT instead of USER_KEEP when log injection is enabled,
+        // meaning resource rules are not applied & instead global sampling is applied
+        // Now gets USER_KEEP because resource rules are applied
+        assertObjectContains(payload, [[{ metrics: { _sampling_priority_v1: USER_KEEP } }]])
+      }, 20000, 1)
+    })
+
+    it('should correctly apply rule based sampling when log injection is disabled', async () => {
+      env = {
+        AGENT_PORT: agent.port,
+        lOG_INJECTION: 'false'
+      }
+      proc = await spawnProc(app, { cwd, env, execArgv: [] })
+      const url = proc.url + '/sampled'
+      return curlAndAssertMessage(agent, url, ({ headers, payload }) => {
+        assertObjectContains(payload, [[{ metrics: { _sampling_priority_v1: USER_KEEP } }]])
+      }, 20000, 1)
+    })
+  })
+})

integration-tests/log_injection/index.js

@@ -0,0 +1,50 @@
+'use strict'
+
+const options = {
+  service: 'test-service',
+  sampleRate: 0.0,
+  samplingRules: [
+    {
+      resource: 'GET /sampled',
+      sampleRate: 1.0
+    }
+  ]
+}
+
+if (process.env.AGENT_PORT) {
+  options.port = process.env.AGENT_PORT
+}
+
+if (process.env.lOG_INJECTION) {
+  options.logInjection = process.env.lOG_INJECTION
+}
+
+const tracer = require('dd-trace')
+tracer.init(options)
+
+const express = require('express')
+const winston = require('winston')
+
+const app = express()
+
+// Create winston logger
+const logger = winston.createLogger({
+  level: 'info',
+  format: winston.format.json(),
+  transports: [
+    new winston.transports.Console({ silent: true })
+  ]
+})
+
+// Route WITH logging (demonstrates the bug)
+app.get('/sampled', (req, res) => {
+  // BUG: This winston.info() triggers log injection BEFORE resource.name is set
+  // which causes sampling decision to happen too early, bypassing the resource rule
+  logger.info('Processing GET /sampled request')
+  res.json({ message: 'logged request' })
+})
+
+const server = app.listen(0, () => {
+  const port = server.address().port
+  process.send({ port })
+})

packages/dd-trace/src/opentracing/tracer.js

@@ -86,7 +86,7 @@ class DatadogTracer {
     }
 
     try {
-      if (format !== 'text_map_dsm') {
+      if (format !== 'text_map_dsm' && format !== formats.LOG) {
         this._prioritySampler.sample(context)
       }
       this._propagators[format].inject(context, carrier)

packages/dd-trace/test/opentracing/tracer.spec.js

@@ -5,6 +5,7 @@ require('../setup/tap')
 const opentracing = require('opentracing')
 const os = require('os')
 const SpanContext = require('../../src/opentracing/span_context')
+const formats = require('../../../../ext/formats')
 const Reference = opentracing.Reference
 
 describe('Tracer', () => {
@@ -25,6 +26,7 @@ describe('Tracer', () => {
   let TextMapPropagator
   let HttpPropagator
   let BinaryPropagator
+  let LogPropagator
   let propagator
   let config
   let log
@@ -58,6 +60,7 @@ describe('Tracer', () => {
     TextMapPropagator = sinon.stub()
     HttpPropagator = sinon.stub()
     BinaryPropagator = sinon.stub()
+    LogPropagator = sinon.stub()
     propagator = {
       inject: sinon.stub(),
       extract: sinon.stub()
@@ -90,6 +93,7 @@ describe('Tracer', () => {
       './propagation/text_map': TextMapPropagator,
       './propagation/http': HttpPropagator,
       './propagation/binary': BinaryPropagator,
+      './propagation/log': LogPropagator,
       '../log': log,
       '../exporter': exporter
     })
@@ -368,6 +372,16 @@ describe('Tracer', () => {
 
       expect(prioritySampler.sample).to.have.been.calledWith(spanContext)
     })
+
+    it('should not generate sampling priority for log injection', () => {
+      LogPropagator.returns(propagator)
+
+      tracer = new Tracer(config)
+      tracer.inject(spanContext, formats.LOG, carrier)
+
+      expect(prioritySampler.sample).to.not.have.been.called
+      expect(propagator.inject).to.have.been.calledWith(spanContext, carrier)
+    })
   })
 
   describe('extract', () => {