fix(instrumentation): surface late-load framework warning regardless of startupLogs (#9068)

* fix(instrumentation): surface late-load framework warning regardless of startupLogs

The Next.js late-load warning was gated on startupLogs, which applyV5Overrides
defaults to off on v5. The users it targets run with no diagnostics enabled, so
the gate hid it from exactly the people whose integration had silently no-op'd.
It now flushes unconditionally through the always-on writer, independent of the
startupLogs-gated startup-log diagnostics, and drops the DATADOG TRACER
DIAGNOSTIC prefix that marked it as one.

Refs: #5430
Refs: #5432

* fix(instrumentation): keep broad load-order warnings behind startupLogs

Only the curated framework warnings (Next.js) must surface unconditionally: a
silently-disabled integration has no other signal. The broad "package X was
loaded before dd-trace" list is startup-diagnostic detail, gated behind
startupLogs with the DATADOG TRACER DIAGNOSTIC prefix and moved to its own queue
so the DD_TRACE_DEBUG-gated conflict warnings are unaffected.

* fix(instrumentation): prefix the Next.js late-load warning

The curated framework warning and the broad load-order list are the same kind of
diagnostic, so both carry the DATADOG TRACER DIAGNOSTIC prefix. The prefix is a
source marker, not a gating signal; the Next.js warning stays unconditional.

* test(instrumentation): pin late-load warning behavior across startupLogs

The subprocess tests only ran the warnings with startupLogs on (its v6 default),
so neither the unconditional Next.js warning nor the startupLogs gate on the broad
list was pinned: a regression on either would still pass on v6. Add the
startupLogs=off cases for both.

Drive-by fix:

* Trim the load-order warning comments to the why.

Author: BridgeAR

packages/datadog-instrumentations/src/helpers/check-require-cache.js

@@ -1,11 +1,9 @@
 'use strict'
 
-// This code runs before the tracer is configured and before a logger is ready
-// For that reason we queue up the messages now and decide what to do with them later
-const warnings = []
-// Same idea, but for the high-signal framework warnings that surface by default
-// (see flushFrameworkWarnings) rather than only under DD_TRACE_DEBUG.
-const frameworkWarnings = []
+// Queued before the logger is ready; flushed once the tracer knows its config.
+const warnings = [] // conflicts; flushed under DD_TRACE_DEBUG
+const loadOrderWarnings = [] // "loaded before dd-trace"; flushed under startupLogs
+const frameworkWarnings = [] // curated (e.g. Next.js); flushed unconditionally
 
 /**
  * Here we maintain a list of packages that an application
@@ -65,11 +63,11 @@ const earlyLoadFrameworks = new Map([
  * unsupported version then a warning would still be displayed.
  * This is OK as the tracer should be loaded earlier anyway.
  *
- * Curated frameworks (see `earlyLoadFrameworks`) are collected regardless of
- * `debug`, since they surface by default; the broad list stays debug-only.
- * @param {boolean} debug Whether to also queue the broad DD_TRACE_DEBUG-only warnings.
+ * Curated frameworks (see `earlyLoadFrameworks`) surface unconditionally; the
+ * broad list of packages loaded before dd-trace is queued for the startupLogs-
+ * gated flush (`flushLoadOrderWarnings`).
  */
-module.exports.checkForRequiredModules = function (debug) {
+module.exports.checkForRequiredModules = function () {
   const packages = require('./hooks')
   const naughties = new Set()
   const frameworksSeen = new Set()
@@ -84,8 +82,8 @@ module.exports.checkForRequiredModules = function (debug) {
 
     // A curated framework loads its own server before user code, so its server
     // module being cached means dd-trace was too late to instrument it. These
-    // surface by default (see flushFrameworkWarnings) with an actionable
-    // message, so they never fall through to the DD_TRACE_DEBUG-only list below.
+    // surface unconditionally (see flushFrameworkWarnings) with an actionable
+    // message, so they never fall through to the broad load-order list below.
     const framework = earlyLoadFrameworks.get(pkg)
     if (framework !== undefined) {
       if (!frameworksSeen.has(pkg) && path?.endsWith(framework.file)) {
@@ -100,15 +98,17 @@ module.exports.checkForRequiredModules = function (debug) {
       continue
     }
 
-    if (!debug || naughties.has(pkg) || !(pkg in packages)) continue
+    if (naughties.has(pkg) || !(pkg in packages)) continue
 
-    warnings.push(() => `Warning: Package '${pkg}' was loaded before dd-trace! This may break instrumentation.`)
+    loadOrderWarnings.push(
+      () => `Warning: Package '${pkg}' was loaded before dd-trace! This may break instrumentation.`
+    )
 
     naughties.add(pkg)
     didWarn = true
   }
 
-  if (didWarn) warnings.push('Warning: Please ensure dd-trace is loaded before other modules.')
+  if (didWarn) loadOrderWarnings.push('Warning: Please ensure dd-trace is loaded before other modules.')
 }
 
 /**
@@ -152,10 +152,24 @@ module.exports.flushStartupLogs = function (log) {
   }
 }
 
+/**
+ * Drains the broad "loaded before dd-trace" warnings collected by
+ * `checkForRequiredModules`. The tracer gates this on startupLogs (these are
+ * startup diagnostics), unlike the unconditional `flushFrameworkWarnings`.
+ * @param {(message: string) => void} warn
+ */
+module.exports.flushLoadOrderWarnings = function (warn) {
+  while (loadOrderWarnings.length) {
+    const entry = loadOrderWarnings.shift()
+    warn(typeof entry === 'function' ? entry() : entry)
+  }
+}
+
 /**
  * Drains the framework warnings collected by `checkForRequiredModules`. The
- * caller surfaces them by default (gated on startupLogs), unlike the
- * DD_TRACE_DEBUG-only `flushStartupLogs` queue.
+ * tracer surfaces these unconditionally (not gated on startupLogs or
+ * DD_TRACE_DEBUG), unlike the DD_TRACE_DEBUG-only `flushStartupLogs` queue,
+ * because the affected users run with neither enabled (#5430 / #5432).
  * @param {(message: string) => void} warn
  */
 module.exports.flushFrameworkWarnings = function (warn) {

packages/datadog-instrumentations/src/helpers/register.js

@@ -38,7 +38,7 @@ if (!disabledInstrumentations.has('process')) {
 }
 
 const debugEnabled = DD_TRACE_DEBUG
-checkRequireCache.checkForRequiredModules(debugEnabled)
+checkRequireCache.checkForRequiredModules()
 if (debugEnabled) {
   setImmediate(checkRequireCache.checkForPotentialConflicts)
 }

packages/datadog-instrumentations/test/helpers/check-require-cache.spec.js

@@ -13,7 +13,7 @@ describe('check-require-cache', () => {
   const opts = {
     cwd: __dirname,
     env: {
-      DD_TRACE_DEBUG: 'true',
+      DD_TRACE_STARTUP_LOGS: 'true',
     },
   }
 
@@ -33,6 +33,15 @@ describe('check-require-cache', () => {
     })
   })
 
+  it('stays silent about late-loaded packages when startupLogs is off', (done) => {
+    const off = { cwd: __dirname, env: { DD_TRACE_STARTUP_LOGS: 'false' } }
+    exec(`${process.execPath} ./check-require-cache/bad-order.js`, off, (error, stdout, stderr) => {
+      assert.strictEqual(error, null)
+      assert.doesNotMatch(stderr, /Package 'express' was loaded/)
+      done()
+    })
+  })
+
   describe('frameworks that must load before the tracer', () => {
     // No DD_TRACE_DEBUG here on purpose: the framework warning has to surface by
     // default, since the users hitting this (issues #5430 / #5432) never turned
@@ -50,6 +59,15 @@ describe('check-require-cache', () => {
       })
     })
 
+    it('warns about next even when startupLogs is off (the v5 default)', (done) => {
+      const off = { cwd: __dirname, env: { DD_TRACE_STARTUP_LOGS: 'false' } }
+      exec(`${process.execPath} ./check-require-cache/next-loaded-first.js`, off, (error, stdout, stderr) => {
+        assert.strictEqual(error, null)
+        assert.match(stderr, /DATADOG TRACER DIAGNOSTIC - 'next' was loaded before dd-trace/)
+        done()
+      })
+    })
+
     it('should not warn when next is loaded after the tracer', (done) => {
       exec(`${process.execPath} ./check-require-cache/next-loaded-after.js`, defaultOpts, (error, stdout, stderr) => {
         assert.strictEqual(error, null)
@@ -90,8 +108,21 @@ describe('check-require-cache', () => {
         path.join('/app', 'node_modules', 'next', 'dist', 'server', 'next-server.js')
       )
       try {
-        checkForRequiredModules(false)
+        checkForRequiredModules()
+        assert.ok(drainFrameworkWarnings().some(message => message.includes("'next' was loaded before dd-trace")))
+      } finally {
+        restore()
+      }
+    })
+
+    it('drains collected warnings so a second flush does not repeat them', () => {
+      const restore = cacheModule(
+        path.join('/app', 'node_modules', 'next', 'dist', 'server', 'next-server.js')
+      )
+      try {
+        checkForRequiredModules()
         assert.ok(drainFrameworkWarnings().some(message => message.includes("'next' was loaded before dd-trace")))
+        assert.deepStrictEqual(drainFrameworkWarnings(), [])
       } finally {
         restore()
       }
@@ -101,7 +132,7 @@ describe('check-require-cache', () => {
       // Literal backslash key reproduces a Windows require.cache entry on any OS.
       const restore = cacheModule('C:\\app\\node_modules\\next\\dist\\server\\next-server.js')
       try {
-        checkForRequiredModules(false)
+        checkForRequiredModules()
         assert.ok(drainFrameworkWarnings().some(message => message.includes("'next' was loaded before dd-trace")))
       } finally {
         restore()
@@ -111,12 +142,12 @@ describe('check-require-cache', () => {
     it('ignores non-server files of a curated framework', () => {
       const nextWarnings = messages => messages.filter(message => message.includes("'next'")).length
 
-      checkForRequiredModules(false)
+      checkForRequiredModules()
       const before = nextWarnings(drainFrameworkWarnings())
 
       const restore = cacheModule(path.join('/app', 'node_modules', 'next', 'package.json'))
       try {
-        checkForRequiredModules(false)
+        checkForRequiredModules()
         // Caching only a non-server file must not add a warning, regardless of
         // whatever else is already in the real require.cache.
         assert.strictEqual(nextWarnings(drainFrameworkWarnings()), before)
@@ -128,7 +159,7 @@ describe('check-require-cache', () => {
     it('does not collect packages outside the curated set', () => {
       const restore = cacheModule(path.join('/app', 'node_modules', 'express', 'lib', 'express.js'))
       try {
-        checkForRequiredModules(false)
+        checkForRequiredModules()
         assert.ok(drainFrameworkWarnings().every(message => !message.includes("'express'")))
       } finally {
         restore()

packages/dd-trace/src/proxy.js

@@ -5,7 +5,7 @@ const DatadogTracer = require('./tracer')
 const getConfig = require('./config')
 const runtimeMetrics = require('./runtime_metrics')
 const log = require('./log')
-const { setStartupLogPluginManager, startupLog, logLateLoadedFrameworks } = require('./startup-log')
+const { setStartupLogPluginManager, startupLog } = require('./startup-log')
 const DynamicInstrumentation = require('./debugger')
 const telemetry = require('./telemetry')
 const nomenclature = require('./service-naming')
@@ -314,7 +314,6 @@ class Tracer extends NoopProxy {
       DynamicInstrumentation.configure(config)
       setStartupLogPluginManager(this._pluginManager)
       startupLog()
-      logLateLoadedFrameworks()
     }
   }
 

packages/dd-trace/src/startup-log.js

@@ -3,7 +3,6 @@
 const os = require('os')
 const { inspect } = require('util')
 const tracerVersion = require('../../../package.json').version
-const { flushFrameworkWarnings } = require('../../datadog-instrumentations/src/helpers/check-require-cache')
 const { warn } = require('./log/writer')
 
 const errors = {}
@@ -71,22 +70,6 @@ function logGenericError (message) {
   warn('DATADOG TRACER DIAGNOSTIC - Generic Error: ' + message)
 }
 
-/**
- * Surfaces the framework warnings collected by `checkForRequiredModules` (e.g.
- * Next.js loaded before dd-trace, so its integration silently no-ops). Gated on
- * startupLogs like the other diagnostics rather than behind DD_TRACE_DEBUG,
- * since the affected users never have debug logging on. Draining makes repeat
- * calls idempotent.
- * @see https://github.com/DataDog/dd-trace-js/issues/5430
- */
-function logLateLoadedFrameworks () {
-  if (!config?.startupLogs) {
-    return
-  }
-
-  flushFrameworkWarnings(message => warn('DATADOG TRACER DIAGNOSTIC - ' + message))
-}
-
 /**
  * Returns config info without integrations (used by startupLog).
  * @returns {Record<string, unknown>}
@@ -162,7 +145,6 @@ module.exports = {
   startupLog,
   logIntegrations,
   logAgentError,
-  logLateLoadedFrameworks,
   setStartupLogConfig,
   setStartupLogPluginManager,
   setSamplingRules,

packages/dd-trace/src/tracer.js

@@ -2,14 +2,22 @@
 
 const tags = require('../../../ext/tags')
 const { ERROR_MESSAGE, ERROR_TYPE, ERROR_STACK } = require('../../dd-trace/src/constants')
-const { flushStartupLogs } = require('../../datadog-instrumentations/src/helpers/check-require-cache')
+const {
+  flushStartupLogs,
+  flushFrameworkWarnings,
+  flushLoadOrderWarnings,
+} = require('../../datadog-instrumentations/src/helpers/check-require-cache')
 const Tracer = require('./opentracing/tracer')
 const Scope = require('./scope')
 const { isError } = require('./util')
 const { setStartupLogConfig } = require('./startup-log')
 const { DataStreamsCheckpointer, DataStreamsManager, DataStreamsProcessor } = require('./datastreams')
 const { IS_SERVERLESS } = require('./serverless')
 const log = require('./log')
+// Always-on writer (console.warn), not the channel-gated `log`: these surface regardless of
+// DD_TRACE_DEBUG.
+const { warn } = require('./log/writer')
+const logDiagnostic = message => warn('DATADOG TRACER DIAGNOSTIC - ' + message)
 
 const SPAN_TYPE = tags.SPAN_TYPE
 const RESOURCE_NAME = tags.RESOURCE_NAME
@@ -25,6 +33,12 @@ class DatadogTracer extends Tracer {
     this._scope = new Scope()
     setStartupLogConfig(config)
     flushStartupLogs(log)
+    // Curated frameworks (e.g. Next.js) silently no-op when loaded first and their users enable
+    // no logging (#5430 / #5432), so surface those unconditionally.
+    flushFrameworkWarnings(logDiagnostic)
+    if (config.startupLogs) {
+      flushLoadOrderWarnings(logDiagnostic)
+    }
 
     if (!IS_SERVERLESS) {
       const storeConfig = require('./tracer_metadata')

packages/dd-trace/test/startup-log.spec.js

@@ -226,67 +226,6 @@ describe('startup log guards', () => {
   })
 })
 
-describe('logLateLoadedFrameworks', () => {
-  const Module = require('node:module')
-  const path = require('node:path')
-  const {
-    checkForRequiredModules,
-    flushFrameworkWarnings,
-  } = require('../../datadog-instrumentations/src/helpers/check-require-cache')
-  const nextServer = path.join('/app', 'node_modules', 'next', 'dist', 'server', 'next-server.js')
-
-  // Reproduce the detection step: cache next's server module, then run the scan
-  // that collects the warning logLateLoadedFrameworks later surfaces.
-  function collectNextWarning () {
-    const fakeModule = new Module(nextServer)
-    fakeModule.exports = {}
-    fakeModule.loaded = true
-    require.cache[nextServer] = fakeModule
-    checkForRequiredModules(false)
-  }
-
-  afterEach(() => {
-    sinon.restore()
-    delete require.cache[nextServer]
-    flushFrameworkWarnings(() => {})
-  })
-
-  it('warns when a curated framework was loaded before the tracer', () => {
-    const warnStub = sinon.stub(console, 'warn')
-    delete require.cache[require.resolve('../src/startup-log')]
-    const { setStartupLogConfig, logLateLoadedFrameworks } = require('../src/startup-log')
-    collectNextWarning()
-    setStartupLogConfig({ startupLogs: true })
-    logLateLoadedFrameworks()
-    const message = warnStub.firstCall.args[0]
-    assert.match(message, /'next' was loaded before dd-trace/)
-    assert.match(message, /--require dd-trace\/init/)
-    assert.match(message, /--import dd-trace\/initialize\.mjs/)
-    assert.match(message, /serverExternalPackages/)
-  })
-
-  it('does not warn when startupLogs is false', () => {
-    const warnStub = sinon.stub(console, 'warn')
-    delete require.cache[require.resolve('../src/startup-log')]
-    const { setStartupLogConfig, logLateLoadedFrameworks } = require('../src/startup-log')
-    collectNextWarning()
-    setStartupLogConfig({ startupLogs: false })
-    logLateLoadedFrameworks()
-    assert.strictEqual(warnStub.callCount, 0)
-  })
-
-  it('drains so a second call does not repeat the warning', () => {
-    const warnStub = sinon.stub(console, 'warn')
-    delete require.cache[require.resolve('../src/startup-log')]
-    const { setStartupLogConfig, logLateLoadedFrameworks } = require('../src/startup-log')
-    collectNextWarning()
-    setStartupLogConfig({ startupLogs: true })
-    logLateLoadedFrameworks()
-    logLateLoadedFrameworks()
-    assert.strictEqual(warnStub.callCount, 1)
-  })
-})
-
 describe('data_streams_enabled', () => {
   afterEach(() => {
     delete process.env.DD_DATA_STREAMS_ENABLED