[test visibility] Add option to automatically report logs within test…

…s when using `winston` (#4762)

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

@@ -0,0 +1,207 @@
+'use strict'
+
+const { exec } = require('child_process')
+
+const { assert } = require('chai')
+const getPort = require('get-port')
+
+const {
+  createSandbox,
+  getCiVisAgentlessConfig,
+  getCiVisEvpProxyConfig
+} = require('./helpers')
+const { FakeCiVisIntake } = require('./ci-visibility-intake')
+const webAppServer = require('./ci-visibility/web-app-server')
+const { NODE_MAJOR } = require('../version')
+
+const cucumberVersion = NODE_MAJOR <= 16 ? '9' : 'latest'
+
+describe('test visibility automatic log submission', () => {
+  let sandbox, cwd, receiver, childProcess, webAppPort
+  let testOutput = ''
+
+  before(async () => {
+    sandbox = await createSandbox([
+      'mocha',
+      `@cucumber/cucumber@${cucumberVersion}`,
+      'jest',
+      'winston',
+      'chai@4'
+    ], true)
+    cwd = sandbox.folder
+    webAppPort = await getPort()
+    webAppServer.listen(webAppPort)
+  })
+
+  after(async () => {
+    await sandbox.remove()
+    await new Promise(resolve => webAppServer.close(resolve))
+  })
+
+  beforeEach(async function () {
+    const port = await getPort()
+    receiver = await new FakeCiVisIntake(port).start()
+  })
+
+  afterEach(async () => {
+    testOutput = ''
+    childProcess.kill()
+    await receiver.stop()
+  })
+
+  const testFrameworks = [
+    {
+      name: 'mocha',
+      command: 'mocha ./ci-visibility/automatic-log-submission/automatic-log-submission-test.js'
+    },
+    {
+      name: 'jest',
+      command: 'node ./node_modules/jest/bin/jest --config ./ci-visibility/automatic-log-submission/config-jest.js'
+    },
+    {
+      name: 'cucumber',
+      command: './node_modules/.bin/cucumber-js ci-visibility/automatic-log-submission-cucumber/*.feature'
+    }
+  ]
+
+  testFrameworks.forEach(({ name, command }) => {
+    context(`with ${name}`, () => {
+      it('can automatically submit logs', (done) => {
+        let logIds, testIds
+
+        const logsPromise = receiver
+          .gatherPayloadsMaxTimeout(({ url }) => url.includes('/api/v2/logs'), payloads => {
+            payloads.forEach(({ headers }) => {
+              assert.equal(headers['dd-api-key'], '1')
+            })
+            const logMessages = payloads.flatMap(({ logMessage }) => logMessage)
+            const [url] = payloads.flatMap(({ url }) => url)
+
+            assert.equal(url, '/api/v2/logs?ddsource=winston&service=my-service')
+            assert.equal(logMessages.length, 2)
+
+            logMessages.forEach(({ dd, level }) => {
+              assert.equal(level, 'info')
+              assert.equal(dd.service, 'my-service')
+              assert.hasAllKeys(dd, ['trace_id', 'span_id', 'service'])
+            })
+
+            assert.includeMembers(logMessages.map(({ message }) => message), [
+              'Hello simple log!',
+              'sum function being called'
+            ])
+
+            logIds = {
+              logSpanId: logMessages[0].dd.span_id,
+              logTraceId: logMessages[0].dd.trace_id
+            }
+          })
+
+        const eventsPromise = receiver
+          .gatherPayloadsMaxTimeout(({ url }) => url.endsWith('/api/v2/citestcycle'), (payloads) => {
+            const events = payloads.flatMap(({ payload }) => payload.events)
+            const testEventContent = events.find(event => event.type === 'test').content
+
+            testIds = {
+              testSpanId: testEventContent.span_id.toString(),
+              testTraceId: testEventContent.trace_id.toString()
+            }
+          })
+
+        childProcess = exec(command,
+          {
+            cwd,
+            env: {
+              ...getCiVisAgentlessConfig(receiver.port),
+              DD_AGENTLESS_LOG_SUBMISSION_ENABLED: '1',
+              DD_AGENTLESS_LOG_SUBMISSION_URL: `http://localhost:${receiver.port}`,
+              DD_API_KEY: '1',
+              DD_SERVICE: 'my-service'
+            },
+            stdio: 'pipe'
+          }
+        )
+        childProcess.on('exit', () => {
+          Promise.all([logsPromise, eventsPromise]).then(() => {
+            const { logSpanId, logTraceId } = logIds
+            const { testSpanId, testTraceId } = testIds
+            assert.include(testOutput, 'Hello simple log!')
+            assert.include(testOutput, 'sum function being called')
+            // cucumber has `cucumber.step`, and that's the active span, not the test.
+            // logs are queried by trace id, so it should be OK
+            if (name !== 'cucumber') {
+              assert.include(testOutput, `"span_id":"${testSpanId}"`)
+              assert.equal(logSpanId, testSpanId)
+            }
+            assert.include(testOutput, `"trace_id":"${testTraceId}"`)
+            assert.equal(logTraceId, testTraceId)
+            done()
+          }).catch(done)
+        })
+
+        childProcess.stdout.on('data', (chunk) => {
+          testOutput += chunk.toString()
+        })
+        childProcess.stderr.on('data', (chunk) => {
+          testOutput += chunk.toString()
+        })
+      })
+
+      it('does not submit logs when DD_AGENTLESS_LOG_SUBMISSION_ENABLED is not set', (done) => {
+        childProcess = exec(command,
+          {
+            cwd,
+            env: {
+              ...getCiVisAgentlessConfig(receiver.port),
+              DD_AGENTLESS_LOG_SUBMISSION_URL: `http://localhost:${receiver.port}`,
+              DD_SERVICE: 'my-service'
+            },
+            stdio: 'pipe'
+          }
+        )
+        childProcess.on('exit', () => {
+          assert.include(testOutput, 'Hello simple log!')
+          assert.notInclude(testOutput, 'span_id')
+          done()
+        })
+
+        childProcess.stdout.on('data', (chunk) => {
+          testOutput += chunk.toString()
+        })
+        childProcess.stderr.on('data', (chunk) => {
+          testOutput += chunk.toString()
+        })
+      })
+
+      it('does not submit logs when DD_AGENTLESS_LOG_SUBMISSION_ENABLED is set but DD_API_KEY is not', (done) => {
+        childProcess = exec(command,
+          {
+            cwd,
+            env: {
+              ...getCiVisEvpProxyConfig(receiver.port),
+              DD_AGENTLESS_LOG_SUBMISSION_ENABLED: '1',
+              DD_AGENTLESS_LOG_SUBMISSION_URL: `http://localhost:${receiver.port}`,
+              DD_SERVICE: 'my-service',
+              DD_TRACE_DEBUG: '1',
+              DD_TRACE_LOG_LEVEL: 'warn',
+              DD_API_KEY: ''
+            },
+            stdio: 'pipe'
+          }
+        )
+        childProcess.on('exit', () => {
+          assert.include(testOutput, 'Hello simple log!')
+          assert.include(testOutput, 'no automatic log submission will be performed')
+          done()
+        })
+
+        childProcess.stdout.on('data', (chunk) => {
+          testOutput += chunk.toString()
+        })
+        childProcess.stderr.on('data', (chunk) => {
+          testOutput += chunk.toString()
+        })
+      })
+    })
+  })
+})

integration-tests/ci-visibility-intake.js

@@ -208,6 +208,15 @@ class FakeCiVisIntake extends FakeAgent {
       })
     })
 
+    app.post('/api/v2/logs', express.json(), (req, res) => {
+      res.status(200).send('OK')
+      this.emit('message', {
+        headers: req.headers,
+        url: req.url,
+        logMessage: req.body
+      })
+    })
+
     return new Promise((resolve, reject) => {
       const timeoutObj = setTimeout(() => {
         reject(new Error('Intake timed out starting up'))

integration-tests/ci-visibility/automatic-log-submission-cucumber/automatic-log-submission.feature

@@ -0,0 +1,4 @@
+Feature: Automatic Log Submission
+  Scenario: Run Automatic Log Submission
+    When we run a test
+    Then I should have made a log

integration-tests/ci-visibility/automatic-log-submission-cucumber/support/logger.js

@@ -0,0 +1,10 @@
+const { createLogger, format, transports } = require('winston')
+
+module.exports = createLogger({
+  level: 'info',
+  exitOnError: false,
+  format: format.json(),
+  transports: [
+    new transports.Console()
+  ]
+})

integration-tests/ci-visibility/automatic-log-submission-cucumber/support/steps.js

@@ -0,0 +1,14 @@
+const { expect } = require('chai')
+const { When, Then } = require('@cucumber/cucumber')
+
+const logger = require('./logger')
+const sum = require('./sum')
+
+Then('I should have made a log', async function () {
+  expect(true).to.equal(true)
+  expect(sum(1, 2)).to.equal(3)
+})
+
+When('we run a test', async function () {
+  logger.log('info', 'Hello simple log!')
+})

integration-tests/ci-visibility/automatic-log-submission-cucumber/support/sum.js

@@ -0,0 +1,6 @@
+const logger = require('./logger')
+
+module.exports = function (a, b) {
+  logger.log('info', 'sum function being called')
+  return a + b
+}

integration-tests/ci-visibility/automatic-log-submission/automatic-log-submission-test.js

@@ -0,0 +1,13 @@
+const { expect } = require('chai')
+
+const logger = require('./logger')
+const sum = require('./sum')
+
+describe('test', () => {
+  it('should return true', () => {
+    logger.log('info', 'Hello simple log!')
+
+    expect(true).to.be.true
+    expect(sum(1, 2)).to.equal(3)
+  })
+})

integration-tests/ci-visibility/automatic-log-submission/config-jest.js

@@ -0,0 +1,8 @@
+module.exports = {
+  projects: [],
+  testPathIgnorePatterns: ['/node_modules/'],
+  cache: false,
+  testMatch: [
+    '**/ci-visibility/automatic-log-submission/automatic-log-submission-*'
+  ]
+}

integration-tests/ci-visibility/automatic-log-submission/logger.js

@@ -0,0 +1,10 @@
+const { createLogger, format, transports } = require('winston')
+
+module.exports = createLogger({
+  level: 'info',
+  exitOnError: false,
+  format: format.json(),
+  transports: [
+    new transports.Console()
+  ]
+})

integration-tests/ci-visibility/automatic-log-submission/sum.js

@@ -0,0 +1,6 @@
+const logger = require('./logger')
+
+module.exports = function (a, b) {
+  logger.log('info', 'sum function being called')
+  return a + b
+}

integration-tests/selenium/selenium.spec.js

@@ -18,7 +18,7 @@ const {
 } = require('../../packages/dd-trace/src/plugins/util/test')
 const { NODE_MAJOR } = require('../../version')
 
-const cucumberVersion = NODE_MAJOR <= 16 ? '9' : '10'
+const cucumberVersion = NODE_MAJOR <= 16 ? '9' : 'latest'
 
 const webAppServer = require('../ci-visibility/web-app-server')
 

packages/datadog-instrumentations/src/jest.js

@@ -850,7 +850,8 @@ addHook({
 }, jestConfigSyncWrapper)
 
 const LIBRARIES_BYPASSING_JEST_REQUIRE_ENGINE = [
-  'selenium-webdriver'
+  'selenium-webdriver',
+  'winston'
 ]
 
 function shouldBypassJestRequireEngine (moduleName) {

packages/datadog-instrumentations/src/winston.js

@@ -8,6 +8,18 @@ const shimmer = require('../../datadog-shimmer')
 
 const patched = new WeakSet()
 
+// Test Visibility log submission channels
+const configureCh = channel('ci:log-submission:winston:configure')
+const addTransport = channel('ci:log-submission:winston:add-transport')
+
+addHook({ name: 'winston', file: 'lib/winston/transports/index.js', versions: ['>=3'] }, transportsPackage => {
+  if (configureCh.hasSubscribers) {
+    configureCh.publish(transportsPackage.Http)
+  }
+
+  return transportsPackage
+})
+
 addHook({ name: 'winston', file: 'lib/winston/logger.js', versions: ['>=3'] }, Logger => {
   const logCh = channel('apm:winston:log')
   shimmer.wrap(Logger.prototype, 'write', write => {
@@ -20,6 +32,16 @@ addHook({ name: 'winston', file: 'lib/winston/logger.js', versions: ['>=3'] }, L
       return write.apply(this, arguments)
     }
   })
+
+  shimmer.wrap(Logger.prototype, 'configure', configure => function () {
+    const configureResponse = configure.apply(this, arguments)
+    // After the original `configure`, because it resets transports
+    if (addTransport.hasSubscribers) {
+      addTransport.publish(this)
+    }
+    return configureResponse
+  })
+
   return Logger
 })