[DI] Fix race condition when applying probe at app boot

integration-tests/debugger/re-evaluation.spec.js

@@ -0,0 +1,150 @@
+'use strict'
+
+const { EOL } = require('node:os')
+const { spawn } = require('node:child_process')
+const { randomUUID } = require('node:crypto')
+const assert = require('node:assert')
+
+const getPort = require('get-port')
+const Axios = require('axios')
+
+const { createSandbox, FakeAgent, assertObjectContains } = require('../helpers')
+const { generateProbeConfig } = require('../../packages/dd-trace/test/debugger/devtools_client/utils')
+
+// A race condition exists where the tracer receives a probe via RC, before Node.js has had a chance to load all the JS
+// files from disk. If this race condition is triggered, it results in the tracer either not being able to find any
+// script to attach the probe to, or, if the probe filename is a bit generic, it finds an incorrect match.
+//
+// If it can't find any script matching the expected filename, instead of emitting an `INSTALLED` event, it emits an
+// `ERROR` event with the message: `No loaded script found for <file>`.
+//
+// If it finds any incorrect match, where it's possible to attach a breakpoint to the line requested, the race
+// condition is a little less obvious, as the tracer just attaches to this wrong script. In this case, the test
+// behavior depends on where the breakpoint ends up being attached. In most cases, the test just times out, as the
+// breakpoint is never exercised during the test, and the tracer therefore never emits the `EMITTING` event.
+//
+// This is only really an issue if Node.js is using the ESM loader, as this is really slow. If the application is
+// purely a CommonJS application, this race condtion will probably never be triggered.
+//
+// This test tries to trigger the race condition. However, it doesn't always happen, so it runs multiple times.
+describe('Dynamic Instrumentation Probe Re-Evaluation', function () {
+  let sandbox
+
+  before(async function () {
+    sandbox = await createSandbox(
+      undefined,
+      undefined,
+      // Ensure the test scripts live in the root of the sandbox so they are always the shortest path when
+      // `findScriptFromPartialPath` is called
+      ['./integration-tests/debugger/target-app/re-evaluation/*']
+    )
+  })
+
+  after(async function () {
+    await sandbox?.remove()
+  })
+
+  describe('Could not find source file', genTestsForSourceFile('unique-filename.js'))
+
+  describe('Initially finds the wrong source file', genTestsForSourceFile('index.js'))
+
+  function genTestsForSourceFile (sourceFile) {
+    return function () {
+      let rcConfig, appPort, agent, proc, axios
+
+      beforeEach(async function () {
+        rcConfig = {
+          product: 'LIVE_DEBUGGING',
+          id: `logProbe_${randomUUID()}`,
+          config: generateProbeConfig({ sourceFile, line: 4 })
+        }
+        appPort = await getPort()
+        agent = await new FakeAgent().start()
+        proc = spawn(
+          process.execPath,
+          ['--import', 'dd-trace/initialize.mjs', sourceFile],
+          {
+            cwd: sandbox.folder,
+            env: {
+              APP_PORT: appPort,
+              DD_DYNAMIC_INSTRUMENTATION_ENABLED: true,
+              DD_TRACE_AGENT_PORT: agent.port,
+              DD_TRACE_DEBUG: process.env.DD_TRACE_DEBUG // inherit to make debugging the sandbox easier
+            }
+          }
+        )
+        proc
+          .on('exit', (code) => {
+            if (code !== 0) {
+              throw new Error(`Child process exited with code ${code}`)
+            }
+          })
+          .on('error', (error) => {
+            throw error
+          })
+        proc.stdout.on('data', log.bind(null, '[child process stdout]'))
+        proc.stderr.on('data', log.bind(null, '[child process stderr]'))
+        axios = Axios.create({
+          baseURL: `http://localhost:${appPort}`
+        })
+      })
+
+      afterEach(async function () {
+        proc?.kill(0)
+        await agent?.stop()
+      })
+
+      for (let attempt = 1; attempt <= 5; attempt++) {
+        const testName = 'should attach probe to the right script, ' +
+          'even if it is not loaded when the probe is received ' +
+          `(attempt ${attempt})`
+
+        it(testName, function (done) {
+          this.timeout(5000)
+
+          const probeId = rcConfig.config.id
+          const expectedPayloads = [{
+            ddsource: 'dd_debugger',
+            service: 're-evaluation-test',
+            debugger: { diagnostics: { probeId, probeVersion: 0, status: 'RECEIVED' } }
+          }, {
+            ddsource: 'dd_debugger',
+            service: 're-evaluation-test',
+            debugger: { diagnostics: { probeId, probeVersion: 0, status: 'INSTALLED' } }
+          }, {
+            ddsource: 'dd_debugger',
+            service: 're-evaluation-test',
+            debugger: { diagnostics: { probeId, probeVersion: 0, status: 'EMITTING' } }
+          }]
+
+          agent.on('debugger-diagnostics', async ({ payload }) => {
+            await Promise.all(payload.map(async (event) => {
+              if (event.debugger.diagnostics.status === 'ERROR') {
+                // shortcut to fail with a more relevant error message in case the target script could not be found,
+                // instead of asserting the entire expected event.
+                assert.fail(event.debugger.diagnostics.exception.message)
+              }
+
+              const expected = expectedPayloads.shift()
+              assertObjectContains(event, expected)
+
+              if (event.debugger.diagnostics.status === 'INSTALLED') {
+                const response = await axios.get('/')
+                assert.strictEqual(response.status, 200)
+              }
+            }))
+
+            if (expectedPayloads.length === 0) done()
+          })
+
+          agent.addRemoteConfig(rcConfig)
+        })
+      }
+    }
+  }
+})
+
+function log (prefix, data) {
+  const msg = data.toString().trim().split(EOL).map((line) => `${prefix} ${line}`).join(EOL)
+  console.log(msg) // eslint-disable-line no-console
+}

integration-tests/debugger/target-app/re-evaluation/index.js

@@ -0,0 +1,7 @@
+import { createServer } from 'node:http'
+
+const server = createServer((req, res) => {
+  res.end('Hello, World!') // This needs to be line 4
+})
+
+server.listen(process.env.APP_PORT)

integration-tests/debugger/target-app/re-evaluation/package.json

@@ -0,0 +1,5 @@
+{
+  "name": "re-evaluation-test",
+  "version": "0.0.0",
+  "type": "module"
+}

integration-tests/debugger/target-app/re-evaluation/unique-filename.js

@@ -0,0 +1,7 @@
+import { createServer } from 'node:http'
+
+const server = createServer((req, res) => {
+  res.end('Hello, World!') // This needs to be line 4
+})
+
+server.listen(process.env.APP_PORT)

packages/dd-trace/src/debugger/devtools_client/breakpoints.js

@@ -9,6 +9,25 @@ const { findScriptFromPartialPath, locationToBreakpoint, breakpointToProbes, pro
 const log = require('../../log')
 
 let sessionStarted = false
+const probes = new Map()
+let scriptLoadingStabilizedResolve
+const scriptLoadingStabilized = new Promise((resolve) => { scriptLoadingStabilizedResolve = resolve })
+
+// There's a race condition when a probe is first added, where the actual script that the probe is supposed to match
+// hasn't been loaded yet. This will result in either the probe not being added at all, or an incorrect script being
+// matched as the probe target.
+//
+// Therefore, once new scripts has been loaded, all probes are re-evaluated. If the matched `scriptId` has changed, we
+// simply remove the old probe (if it was added to the wrong script) and apply it again.
+session.on('scriptLoadingStabilized', () => {
+  log.debug('[debugger:devtools_client] Re-evaluating probes')
+  scriptLoadingStabilizedResolve()
+  for (const probe of probes.values()) {
+    reEvaluateProbe(probe).catch(err => {
+      log.error('[debugger:devtools_client] Error re-evaluating probe %s', probe.id, err)
+    })
+  }
+})
 
 module.exports = {
   addBreakpoint,
@@ -18,13 +37,14 @@ module.exports = {
 async function addBreakpoint (probe) {
   if (!sessionStarted) await start()
 
+  probes.set(probe.id, probe)
+
   const file = probe.where.sourceFile
   let lineNumber = Number(probe.where.lines[0]) // Tracer doesn't support multiple-line breakpoints
   let columnNumber = 0 // Probes do not contain/support column information
 
   // Optimize for sending data to /debugger/v1/input endpoint
   probe.location = { file, lines: [String(lineNumber)] }
-  delete probe.where
 
   // Optimize for fast calculations when probe is hit
   probe.templateRequiresEvaluation = templateRequiresEvaluation(probe.segments)
@@ -47,6 +67,8 @@ async function addBreakpoint (probe) {
   if (!script) throw new Error(`No loaded script found for ${file} (probe: ${probe.id}, version: ${probe.version})`)
   const { url, scriptId, sourceMapURL, source } = script
 
+  probe.scriptId = scriptId // Needed for detecting script changes during re-evaluation
+
   if (sourceMapURL) {
     log.debug(
       '[debugger:devtools_client] Translating location using source map for %s:%d:%d (probe: %s, version: %d)',
@@ -109,6 +131,8 @@ async function removeBreakpoint ({ id }) {
     throw Error(`Unknown probe id: ${id}`)
   }
 
+  probes.delete(id)
+
   const release = await lock()
 
   try {
@@ -173,10 +197,29 @@ async function updateBreakpoint (breakpoint, probe) {
   }
 }
 
-function start () {
+async function reEvaluateProbe (probe) {
+  const script = findScriptFromPartialPath(probe.where.sourceFile)
+  log.debug('[debugger:devtools_client] re-evaluating probe %s: %s => %s', probe.id, probe.scriptId, script?.scriptId)
+
+  if (probe.scriptId !== script?.scriptId) {
+    log.debug('[debugger:devtools_client] Better match found for probe %s, re-evaluating', probe.id)
+    if (probeToLocation.has(probe.id)) {
+      await removeBreakpoint(probe)
+    }
+    await addBreakpoint(probe)
+  }
+}
+
+async function start () {
   sessionStarted = true
   log.debug('[debugger:devtools_client] Starting debugger')
-  return session.post('Debugger.enable')
+  await session.post('Debugger.enable')
+
+  // Wait until there's a pause in script-loading to avoid accidentally adding probes to incorrect scripts. This is not
+  // a guarantee, but best effort.
+  log.debug('[debugger:devtools_client] Waiting for script-loading to stabilize')
+  await scriptLoadingStabilized
+  log.debug('[debugger:devtools_client] Script loading stabilized')
 }
 
 function stop () {

packages/dd-trace/src/debugger/devtools_client/state.js

@@ -9,6 +9,7 @@ const WINDOWS_DRIVE_LETTER_REGEX = /[a-zA-Z]/
 
 const loadedScripts = []
 const scriptUrls = new Map()
+let reEvaluateProbesTimer = null
 
 module.exports = {
   locationToBreakpoint: new Map(),
@@ -93,6 +94,10 @@ module.exports = {
 
   getStackFromCallFrames (callFrames) {
     return callFrames.map((frame) => {
+      // TODO: Possible race condition: If the breakpoint is in the process of being removed, and this is the last
+      // breakpoint, it will also stop the debugging session, which in turn will clear the state, which means clearing
+      // the `scriptUrls` map. That might result in this the `scriptUrls.get` call above returning `undefined`, which
+      // will throw when `startsWith` is called on it.
       let fileName = scriptUrls.get(frame.location.scriptId)
       if (fileName.startsWith('file://')) fileName = fileName.substr(7) // TODO: This might not be required
       return {
@@ -142,5 +147,10 @@ session.on('Debugger.scriptParsed', ({ params }) => {
     } else {
       loadedScripts.push(params)
     }
+
+    clearTimeout(reEvaluateProbesTimer)
+    reEvaluateProbesTimer = setTimeout(() => {
+      session.emit('scriptLoadingStabilized')
+    }, 500)
   }
 })

packages/dd-trace/test/debugger/devtools_client/breakpoints.spec.js

@@ -17,6 +17,9 @@ describe('breakpoints', function () {
         }
         return Promise.resolve({})
       }),
+      on (event, callback) {
+        if (event === 'scriptLoadingStabilized') callback()
+      },
       '@noCallThru': true
     }
 

packages/dd-trace/test/debugger/devtools_client/state.spec.js

@@ -50,7 +50,8 @@ describe('findScriptFromPartialPath', function () {
               }
             })
           }
-        }
+        },
+        emit () {}
       }
     })
   })