Enable log injection by default for structured loggers (#5859)

Author: ida613

integration-tests/automatic-log-submission.spec.js

@@ -174,8 +174,10 @@ describe('test visibility automatic log submission', () => {
         )
         childProcess.on('exit', () => {
           assert.include(testOutput, 'Hello simple log!')
-          assert.notInclude(testOutput, 'span_id')
-          done()
+          assert.include(testOutput, 'span_id')
+          logsPromise.then(() => {
+            done()
+          }).catch(done)
         })
 
         childProcess.stdout.on('data', (chunk) => {
@@ -184,6 +186,13 @@ describe('test visibility automatic log submission', () => {
         childProcess.stderr.on('data', (chunk) => {
           testOutput += chunk.toString()
         })
+
+        const logsPromise = receiver
+          .gatherPayloadsMaxTimeout(({ url }) => url.includes('/api/v2/logs'), payloads => {
+            if (payloads.length > 0) {
+              throw new Error('Unexpected logs')
+            }
+          }, 5000)
       })
 
       it('does not submit logs when DD_AGENTLESS_LOG_SUBMISSION_ENABLED is set but DD_API_KEY is not', (done) => {

integration-tests/pino.spec.js

@@ -1,6 +1,6 @@
 'use strict'
 
-const { FakeAgent, spawnProc, createSandbox, curl } = require('./helpers')
+const { FakeAgent, spawnProc, createSandbox, curl, assertObjectContains } = require('./helpers')
 const path = require('path')
 const { assert } = require('chai')
 const { once } = require('events')
@@ -32,6 +32,27 @@ describe('pino test', () => {
       await agent.stop()
     })
 
+    it('Log injection enabled by default', async () => {
+      proc = await spawnProc(startupTestFile, {
+        cwd,
+        env: {
+          AGENT_PORT: agent.port
+        },
+        stdio: 'pipe',
+      })
+      const [data] = await Promise.all([once(proc.stdout, 'data'), curl(proc)])
+      const stdoutData = JSON.parse(data.toString())
+      assertObjectContains(stdoutData, {
+        dd: {
+          trace_id: stdoutData.custom.trace_id,
+          span_id: stdoutData.custom.span_id
+        },
+        custom: {
+          trace_id: stdoutData.dd.trace_id,
+          span_id: stdoutData.dd.span_id
+        }
+      })
+    })
     it('Log injection enabled', async () => {
       proc = await spawnProc(startupTestFile, {
         cwd,
@@ -60,6 +81,7 @@ describe('pino test', () => {
         cwd,
         env: {
           AGENT_PORT: agent.port,
+          lOG_INJECTION: false
         },
         stdio: 'pipe',
       })

integration-tests/telemetry.spec.js

@@ -66,7 +66,7 @@ describe('telemetry', () => {
       await agent.assertTelemetryReceived(msg => {
         const { configuration } = msg.payload.payload
         assertObjectContains(configuration, [
-          { name: 'DD_LOG_INJECTION', value: false, origin: 'default' },
+          { name: 'DD_LOG_INJECTION', value: 'structured', origin: 'default' },
           { name: 'DD_LOG_INJECTION', value: true, origin: 'env_var' },
           { name: 'DD_LOG_INJECTION', value: false, origin: 'code' }
         ])

packages/datadog-plugin-bunyan/src/index.js

@@ -1,8 +1,8 @@
 'use strict'
 
-const LogPlugin = require('../../dd-trace/src/plugins/log_plugin')
+const StructuredLogPlugin = require('../../dd-trace/src/plugins/structured_log_plugin')
 
-class BunyanPlugin extends LogPlugin {
+class BunyanPlugin extends StructuredLogPlugin {
   static get id () {
     return 'bunyan'
   }

packages/datadog-plugin-bunyan/test/index.spec.js

@@ -49,7 +49,7 @@ describe('Plugin', () => {
 
             const record = JSON.parse(stream.write.firstCall.args[0].toString())
 
-            expect(record).to.not.have.property('dd')
+            expect(record).to.have.property('dd')
           })
         })
       })

packages/datadog-plugin-pino/src/index.js

@@ -1,8 +1,8 @@
 'use strict'
 
-const LogPlugin = require('../../dd-trace/src/plugins/log_plugin')
+const StructuredLogPlugin = require('../../dd-trace/src/plugins/structured_log_plugin')
 
-class PinoPlugin extends LogPlugin {
+class PinoPlugin extends StructuredLogPlugin {
   static get id () {
     return 'pino'
   }

packages/datadog-plugin-pino/test/index.spec.js

@@ -64,7 +64,7 @@ describe('Plugin', () => {
 
               const record = JSON.parse(stream.write.firstCall.args[0].toString())
 
-              expect(record).to.not.have.property('dd')
+              expect(record).to.have.property('dd')
               expect(record).to.have.deep.property('msg', 'message')
             })
           })
@@ -80,8 +80,8 @@ describe('Plugin', () => {
 
                 const record = stream.write.firstCall.args[0].toString()
 
-                expect(record).to.not.include('trace_id')
-                expect(record).to.not.include('span_id')
+                expect(record).to.include('trace_id')
+                expect(record).to.include('span_id')
                 expect(record).to.include('message')
               })
             })

packages/datadog-plugin-winston/src/index.js

@@ -1,8 +1,8 @@
 'use strict'
 
-const LogPlugin = require('../../dd-trace/src/plugins/log_plugin')
+const StructuredLogPlugin = require('../../dd-trace/src/plugins/structured_log_plugin')
 
-class WinstonPlugin extends LogPlugin {
+class WinstonPlugin extends StructuredLogPlugin {
   static get id () {
     return 'winston'
   }

packages/datadog-plugin-winston/test/index.spec.js

@@ -131,7 +131,7 @@ describe('Plugin', () => {
           tracer.scope().activate(span, () => {
             winston.info('message')
 
-            expect(spy).to.not.have.been.calledWithMatch(meta.dd)
+            expect(spy).to.have.been.calledWithMatch(meta.dd)
           })
         })
       })
@@ -336,6 +336,7 @@ describe('Plugin', () => {
             expect(await logServer.logPromise).to.include(meta.dd)
           })
         })
+
         // Only run this test with Winston v3.17.0+ since it uses newer format functions
         if (semver.intersects(version, '>=3.17.0')) {
           describe('with error formatting matching temp.js example', () => {

packages/dd-trace/src/config.js

@@ -545,7 +545,7 @@ class Config {
     defaults.testManagementAttemptToFixRetries = 20
     defaults.isTestManagementEnabled = false
     defaults.isImpactedTestsEnabled = false
-    defaults.logInjection = false
+    defaults.logInjection = 'structured'
     defaults.lookup = undefined
     defaults.inferredProxyServicesEnabled = false
     defaults.memcachedCommandEnabled = false

packages/dd-trace/src/plugins/log_plugin.js

@@ -45,10 +45,14 @@ module.exports = class LogPlugin extends Plugin {
     })
   }
 
+  _isEnabled (config) {
+    return config.enabled && (config.logInjection === true || config.ciVisAgentlessLogSubmissionEnabled)
+  }
+
   configure (config) {
     return super.configure({
       ...config,
-      enabled: config.enabled && (config.logInjection || config.ciVisAgentlessLogSubmissionEnabled)
+      enabled: this._isEnabled(config)
     })
   }
 }

packages/dd-trace/src/plugins/structured_log_plugin.js

@@ -0,0 +1,9 @@
+'use strict'
+
+const LogPlugin = require('./log_plugin')
+
+module.exports = class StructuredLogPlugin extends LogPlugin {
+  _isEnabled (config) {
+    return super._isEnabled(config) || (config.enabled && config.logInjection === 'structured')
+  }
+}

packages/dd-trace/test/config.spec.js

@@ -427,7 +427,10 @@ describe('Config', () => {
       { name: 'langchain.spanPromptCompletionSampleRate', value: 1.0, origin: 'default' },
       { name: 'llmobs.agentlessEnabled', value: undefined, origin: 'default' },
       { name: 'llmobs.mlApp', value: undefined, origin: 'default' },
-      { name: 'logInjection', value: false, origin: 'default' },
+      { name: 'ciVisibilityTestSessionName', value: '', origin: 'default' },
+      { name: 'ciVisAgentlessLogSubmissionEnabled', value: false, origin: 'default' },
+      { name: 'isTestDynamicInstrumentationEnabled', value: false, origin: 'default' },
+      { name: 'logInjection', value: 'structured', origin: 'default' },
       { name: 'lookup', value: undefined, origin: 'default' },
       { name: 'middlewareTracingEnabled', value: true, origin: 'default' },
       { name: 'openai.spanCharLimit', value: 128, origin: 'default' },

packages/dd-trace/test/plugins/log_plugin.spec.js

@@ -3,6 +3,7 @@
 require('../setup/tap')
 
 const LogPlugin = require('../../src/plugins/log_plugin')
+const BunyanPlugin = require('../../../datadog-plugin-bunyan/src/index')
 const Tracer = require('../../src/tracer')
 const Config = require('../../src/config')
 
@@ -29,7 +30,7 @@ const tracer = new Tracer(new Config({
   ...config
 }))
 
-const plugin = new TestLog({
+let plugin = new TestLog({
   _tracer: tracer
 })
 plugin.configure({
@@ -65,4 +66,42 @@ describe('LogPlugin', () => {
       expect(message.dd).to.have.property('span_id', span.context().toSpanId())
     })
   })
+
+  it('should inject logs for only structured loggers when logInjection is structured', () => {
+    plugin.configure({
+      logInjection: 'structured',
+      enabled: true
+    })
+    const unstructuredLoggerSpan = tracer.startSpan('unstructured logger')
+
+    tracer.scope().activate(unstructuredLoggerSpan, () => {
+      const data = { message: {} }
+      testLogChannel.publish(data)
+      const { message } = data
+
+      expect(message.dd).to.be.undefined
+    })
+
+    plugin = new BunyanPlugin({
+      _tracer: tracer
+    })
+    plugin.configure({
+      logInjection: 'structured',
+      enabled: true
+    })
+
+    const structuredLoggerSpan = tracer.startSpan('structured logger')
+    const structuredLogChannel = channel('apm:bunyan:log')
+
+    tracer.scope().activate(structuredLoggerSpan, () => {
+      const data = { message: {} }
+      structuredLogChannel.publish(data)
+      const { message } = data
+
+      expect(message.dd).to.contain(config)
+
+      expect(message.dd).to.have.property('trace_id', structuredLoggerSpan.context().toTraceId(true))
+      expect(message.dd).to.have.property('span_id', structuredLoggerSpan.context().toSpanId())
+    })
+  })
 })