test(integration): cover cold-start module tracing

.github/workflows/integration_tests_local.yml

@@ -59,8 +59,8 @@ jobs:
         with:
           node-version: ${{ matrix.node_version }}
 
-      - name: Test timeout trace assertions
-        run: node --test integration_tests_local/check-timeout-logs.test.js
+      - name: Test structural trace assertions
+        run: node --test integration_tests_local/check-*.test.js
 
       - name: Run local container integration tests (nodejs${{ matrix.node_major }}.x, ${{ matrix.architecture }})
         run: PLATFORM=${{ matrix.platform }} RUNTIME_PARAM=${{ matrix.node_major }} ./integration_tests_local/run.sh

.gitignore

@@ -20,3 +20,4 @@ integration_tests/container/*/datadog-lambda-js-local.tgz
 
 # Local integration test harness binaries
 integration_tests_local/bin/
+integration_tests/container/layer/cold_start_fixture/

integration_tests/container/cjs/Dockerfile

@@ -10,6 +10,9 @@ ARG DD_TRACE_VERSION
 # AWS suite (throw-error, status-code-500s, send-metrics, process-input,
 # http-requests) plus extractor.js for the DD_TRACE_EXTRACTOR case.
 COPY package.json *.js ${LAMBDA_TASK_ROOT}/
+# Known real module loads at each path class; no runtime implementation is overwritten.
+COPY cold-start-probe.js /opt/cold-start-probe.js
+COPY cold-start-probe.js /var/runtime/cold-start-probe.js
 COPY datadog-lambda-js-local.tgz /tmp/datadog-lambda-js-local.tgz
 RUN cd ${LAMBDA_TASK_ROOT} \
     && test -n "$DD_TRACE_VERSION" \

integration_tests/container/cjs/cold-start-parent.js

@@ -0,0 +1,3 @@
+require("./cold-start-probe");
+require("./cold-start-skip");
+process.stdout.write(JSON.stringify({ coldStartFixture: __filename }) + "\n");

integration_tests/container/cjs/cold-start-probe.js

@@ -0,0 +1,4 @@
+// Deliberate fixture-only load cost, well above the 10ms tracing threshold.
+// No busy loop or machine-speed-dependent module count.
+Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, 50);
+process.stdout.write(JSON.stringify({ coldStartFixture: __filename }) + "\n");

integration_tests/container/cjs/cold-start-skip.js

@@ -0,0 +1,2 @@
+require("./cold-start-skipped-child");
+process.stdout.write(JSON.stringify({ coldStartFixture: __filename }) + "\n");

integration_tests/container/cjs/cold-start-skipped-child.js

@@ -0,0 +1,2 @@
+Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, 50);
+process.stdout.write(JSON.stringify({ coldStartFixture: __filename }) + "\n");

integration_tests/container/cjs/cold-start-warm.js

@@ -0,0 +1,2 @@
+Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, 50);
+process.stdout.write(JSON.stringify({ coldStartFixture: __filename }) + "\n");

integration_tests/container/cjs/cold-start.js

@@ -0,0 +1,22 @@
+// Real synchronous module loads, observed through dd-trace's module-load channels.
+require("./cold-start-parent");
+require("/opt/cold-start-probe");
+require("/var/runtime/cold-start-probe");
+
+let invocation = 0;
+exports.handle = (_event, context) => {
+  invocation++;
+  // Lazy loading on a warm invocation is supported: it must be traced once,
+  // parented to that invocation, and not replayed on subsequent invocations.
+  if (invocation === 2) require("./cold-start-warm");
+  process.stdout.write(
+    JSON.stringify({
+      coldStartInvocation: {
+        requestId: context.awsRequestId,
+        invocation,
+        initializationType: process.env.AWS_LAMBDA_INITIALIZATION_TYPE,
+      },
+    }) + "\n",
+  );
+  return { message: "hello, dog!" };
+};

integration_tests/container/layer/Dockerfile

@@ -31,5 +31,8 @@ COPY layer_pkg /opt/nodejs/node_modules/datadog-lambda-js/
 # handler.js (CJS) and esm.mjs (top-level await) are plain unwrapped user
 # handlers; the layer's handler.mjs wraps them via DD_LAMBDA_HANDLER.
 COPY handler.js esm.mjs ${LAMBDA_TASK_ROOT}/
+COPY cold_start_fixture/ ${LAMBDA_TASK_ROOT}/
+COPY cold_start_fixture/cold-start-probe.js /opt/cold-start-probe.js
+COPY cold_start_fixture/cold-start-probe.js /var/runtime/cold-start-probe.js
 
 CMD ["/opt/nodejs/node_modules/datadog-lambda-js/handler.handler"]

integration_tests_local/README.md

@@ -82,6 +82,60 @@ The case names are:
 | `cjs-fetch-requests` | fetch variant of `cjs-http-requests`: the global fetch (undici) is instrumented by a different dd-trace plugin than http/https; mock echo pins the injected headers on that path |
 | `cjs-custom-extractor` | `DD_TRACE_EXTRACTOR=extractor.extract`; asserts `_dd.parent_source: event` on the inferred span |
 | `cjs-proactive-init` | eager-init managed-instances RIE path with a 15 s init→invoke gap; asserts proactive-initialization markers on the raw logs |
+| `cjs-cold-start` / `layer-cold-start` | real init-time module loads through npm redirect and layer entrypoints; one load span, known require spans, parent/timing/classification checks, and warm-load cleanup |
+| `cjs-cold-start-skip` | a known loaded library and its subtree are absent from traces; other fixture modules remain |
+| `cjs-cold-start-threshold` | a high `DD_MIN_COLD_START_DURATION` suppresses require spans while retaining the first-invocation load span |
+| `cjs-cold-start-disabled` | `DD_COLD_START_TRACING=false` suppresses load and require spans, while the handler still loads the same modules |
+| `cjs-cold-start-provisioned` / `cjs-cold-start-managed` | initialization-mode suppression, including a check that the runtime actually applied the requested mode |
+
+### Cold-start tracing: structural oracle, not a log golden
+
+These seven cases run in the same five-runtime, two-architecture CI matrix. They
+use the existing return-value golden and runtime-tag assertion, but intentionally
+do **not** have byte-for-byte log goldens. Module timings determine which nodes
+cross `DD_MIN_COLD_START_DURATION`, so the full tree changes with machine speed.
+Existing cases still disable cold-start tracing and retain their strict goldens;
+the shared normalizer is unchanged.
+
+`check-cold-start-logs.js` checks all raw trace chunks before normalization:
+
+- exactly one invocation span per request, and proof all requests used one warm environment;
+- exactly one `aws.lambda.load`, in the first invocation's trace, parented to the
+  inferred span when present or the invocation otherwise;
+- real known init-time modules under `/var/task`, `/opt`, and `/var/runtime`, with
+  correctly classified require spans ending before invocation start (2ms tolerance
+  for the millisecond module clock versus the tracer clock);
+- connected, acyclic require trees, unique exported identities, and no replay of
+  fixture modules on later invocations;
+- a lazy module loaded on invocation two, parented to that invocation, not another
+  cold-start load span. Warm require spans are legitimate; replaying init modules is not;
+- skip-library/subtree, min-duration, disabled, and initialization-mode controls.
+
+The fixture uses a 50ms `Atomics.wait` during module evaluation, against a 10ms
+threshold. This is intentional fixture-only load cost, not a busy loop or an
+assertion about exact duration. File-load markers prove the modules actually ran
+even when their spans must be suppressed. No synthetic module-load channel
+messages or tracer internals are used to manufacture the integration output.
+Core-module name classification also has a checker unit test; the fixture does
+not require a core module to exceed a real-time threshold.
+
+```bash
+node --test integration_tests_local/check-*.test.js
+RIE_HTTP_TRANSPORT=container RUNTIME_PARAM=22 CASE_PARAM=cjs-cold-start ./integration_tests_local/run.sh
+SKIP_PACK=true RIE_HTTP_TRANSPORT=container RUNTIME_PARAM=22 CASE_PARAM=layer-cold-start ./integration_tests_local/run.sh
+```
+
+The positive cases expose missing module spans with released dd-trace 6.15.0.
+They depend on the failed-load event cleanup in
+[dd-trace-js #10535](https://github.com/DataDog/dd-trace-js/pull/10535).
+Before merging, update the affected tracer pin to a release containing that fix
+and run the full matrix without a local overlay. CI deliberately uses released
+dependencies, with no workaround or expected-failure exemption. Updating snapshots
+cannot repair a structural failure; raw logs are saved under `/tmp/l2-raw-*.log`.
+
+The managed fixture explicitly sets
+`AWS_LAMBDA_NODEJS_WORKER_COUNT=1`: concurrency one alone still allows a multi-worker
+pool and cannot guarantee one module cache across invocations.
 
 Two legacy aliases remain for muscle memory: `VARIANT_PARAM=cjs|esm` maps to
 `container-cjs`/`container-esm`, and `SIMULATE_PROACTIVE_INIT=true` maps to

integration_tests_local/check-cold-start-logs.js

@@ -0,0 +1,130 @@
+"use strict";
+
+const assert = require("node:assert/strict");
+const fs = require("node:fs");
+
+const [mode, count] = process.argv.slice(2);
+const expected = Number(count);
+assert.ok(["enabled", "skip", "threshold", "disabled", "provisioned", "managed"].includes(mode), "known mode");
+assert.ok(Number.isInteger(expected) && expected >= 3, "at least three invocations required");
+const spans = [];
+const starts = [];
+const reports = [];
+const fixtures = [];
+const calls = [];
+// Inspect the unnormalized exports across every payload: a "some trace matches"
+// check would miss duplicate invocation spans or replayed module spans.
+for (const line of fs.readFileSync(0, "utf8").split("\n")) {
+  const start = /^START RequestId: (\S+)/.exec(line);
+  const report = /^REPORT RequestId: (\S+)/.exec(line);
+  if (start) starts.push(start[1]);
+  if (report) reports.push(report[1]);
+  let record;
+  try {
+    record = JSON.parse(line);
+  } catch {
+    continue;
+  }
+  if (Array.isArray(record.traces)) spans.push(...record.traces.flat());
+  if (record.coldStartFixture) fixtures.push(record.coldStartFixture);
+  if (record.coldStartInvocation) calls.push(record.coldStartInvocation);
+}
+assert.equal(starts.length, expected, "START count");
+assert.equal(new Set(starts).size, expected, "unique invocation IDs");
+assert.deepEqual(reports, starts, "REPORT IDs match invocations");
+assert.deepEqual(
+  calls.map((c) => c.requestId),
+  starts,
+  "fixture ran for every invocation",
+);
+assert.deepEqual(
+  calls.map((c) => c.invocation),
+  starts.map((_, i) => i + 1),
+  "same warm environment reused",
+);
+const expectedFixtures = [
+  "/var/task/cold-start-parent.js",
+  "/var/task/cold-start-probe.js",
+  "/var/task/cold-start-skip.js",
+  "/var/task/cold-start-skipped-child.js",
+  "/opt/cold-start-probe.js",
+  "/var/runtime/cold-start-probe.js",
+  "/var/task/cold-start-warm.js",
+];
+// Load markers prove suppression/filter tests actually executed the same modules.
+assert.deepEqual(fixtures.slice().sort(), expectedFixtures.slice().sort(), "known modules really loaded exactly once");
+const lambdas = spans.filter((s) => s.name === "aws.lambda");
+assert.equal(lambdas.length, expected, "exactly one Lambda span per invocation across all payloads");
+const invocations = starts.map((id) => {
+  const matches = lambdas.filter((s) => s.meta?.request_id === id);
+  assert.equal(matches.length, 1, "one Lambda span for request ID");
+  assert.equal(matches[0].error, 0, "successful invocation");
+  return matches[0];
+});
+const cold = spans.filter((s) => s.name === "aws.lambda.load" || s.name.startsWith("aws.lambda.require"));
+const suppressed = ["disabled", "provisioned", "managed"].includes(mode);
+if (mode === "provisioned" || mode === "managed") {
+  const value = mode === "managed" ? "lambda-managed-instances" : "provisioned-concurrency";
+  assert.ok(
+    calls.every((c) => c.initializationType === value),
+    "runtime actually used the requested initialization mode",
+  );
+}
+if (suppressed) {
+  assert.equal(cold.length, 0, "cold-start tracing suppressed, including warm module loads");
+} else {
+  const [first, second] = invocations;
+  const loads = cold.filter((s) => s.name === "aws.lambda.load");
+  assert.equal(loads.length, 1, "exactly one load span; none on warm invocations");
+  const load = loads[0];
+  const key = (s) => `${s.trace_id}/${s.span_id}`;
+  const byId = new Map(spans.map((s) => [key(s), s]));
+  assert.equal(byId.size, spans.length, "no duplicated exported span identities");
+  const parent = (s) => byId.get(`${s.trace_id}/${s.parent_id}`);
+  assert.equal(load.trace_id, first.trace_id, "load belongs to first invocation trace");
+  assert.equal(load.parent_id, parent(first)?.span_id || first.span_id, "load parent is inferred span or invocation");
+  assert.ok(load.duration >= 0 && load.start + load.duration <= first.start + 2e6, "load ends before invocation start");
+  const requires = cold.filter((s) => s.name.startsWith("aws.lambda.require"));
+  if (mode === "threshold") {
+    assert.equal(requires.length, 0, "high min-duration filters require spans but keeps the load span");
+  } else {
+    // Only the deliberately slow fixture modules have fixed cardinality. Other
+    // modules can cross the duration threshold differently on each runtime/CPU.
+    assert.ok(requires.length > 0, "module-load capture is active");
+    for (const span of requires) {
+      const filename = span.meta?.filename;
+      assert.equal(typeof filename, "string", "require span filename");
+      const operation = filename.startsWith("/opt/")
+        ? "aws.lambda.require_layer"
+        : filename.startsWith("/var/runtime/")
+        ? "aws.lambda.require_runtime"
+        : filename.includes("/")
+        ? "aws.lambda.require"
+        : "aws.lambda.require_core_module";
+      assert.equal(span.name, operation, "operation matches module path classification");
+      assert.ok(Number.isFinite(span.duration) && span.duration >= 0, "valid require duration");
+      let ancestor = span;
+      const seen = new Set();
+      while (ancestor && ancestor !== load && !invocations.includes(ancestor)) {
+        assert.ok(!seen.has(key(ancestor)), "acyclic load tree");
+        seen.add(key(ancestor));
+        ancestor = parent(ancestor);
+      }
+      assert.ok(ancestor === load || invocations.includes(ancestor), "require linked to load or invocation");
+    }
+    for (const filename of expectedFixtures) {
+      const matches = requires.filter((s) => s.meta.filename === filename);
+      const skipped = mode === "skip" && /cold-start-skip(?:ped-child)?\.js$/.test(filename);
+      assert.equal(matches.length, skipped ? 0 : 1, `fixture span cardinality: ${filename}`);
+      if (skipped) continue;
+      const span = matches[0];
+      const warm = filename.endsWith("cold-start-warm.js");
+      let ancestor = span;
+      while (ancestor && ancestor !== load && !invocations.includes(ancestor)) ancestor = parent(ancestor);
+      assert.equal(ancestor, warm ? second : load, "cold/warm fixture parent and no replay on later invocations");
+      if (!warm) assert.ok(span.start + span.duration <= first.start + 2e6, "init module finishes before invocation");
+      else assert.ok(span.start >= second.start - 2e6, "lazy module loads during second invocation");
+    }
+  }
+}
+console.log(`Ok: cold-start ${mode} structure across ${expected} invocations`);