[DI] Fix race condition when applying probe at app boot (#5698)

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.

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.

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 would probably never be triggered.

Author: watson

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 () {}
       }
     })
   })