Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions .github/workflows/integration_tests_local.yml
Original file line number Diff line number Diff line change
Expand Up @@ -59,6 +59,9 @@ jobs:
with:
node-version: ${{ matrix.node_version }}

- name: Test timeout trace assertions
run: node --test integration_tests_local/check-timeout-logs.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

Expand Down
11 changes: 11 additions & 0 deletions integration_tests/container/cjs/timeout-handler.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
const tracer = require("dd-trace");

// Both entry paths initialize dd-trace before loading this unwrapped handler.
// The child stays open past the real RIE deadline: only the timeout monitor's
// killAll() can flush it along with the error-tagged invocation span.
exports.handle = async function handle() {
return tracer.trace("timeout.unfinished", async () => {
await new Promise((resolve) => setTimeout(resolve, 60_000));
return { statusCode: 200, body: "unreachable" };
});
};
7 changes: 7 additions & 0 deletions integration_tests/container/cjs/timeout.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,7 @@
// Manual wrapping does not initialize the tracer. Load it first so its
// datadog-lambda-js hook installs the pre-migration timeout monitor.
require("dd-trace").init();
const { datadog } = require("datadog-lambda-js");
const { handle } = require("./timeout-handler");

module.exports.handle = datadog(handle);
137 changes: 131 additions & 6 deletions integration_tests_local/README.md
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
# Local integration tests (docker + AWS RIE, no AWS account required)

This directory contains a **local** integration test harness for
datadog-lambda-js. It runs eleven cases — container-image, layer-mode, and
datadog-lambda-js. It runs container-image, layer-mode, and
manual-wrap handlers, plus targeted feature cases (HTTP header injection,
custom trace extractors, proactive initialization) — inside Docker against the
[AWS Lambda Runtime Interface Emulator (RIE)](https://github.com/aws/aws-lambda-runtime-interface-emulator),
Expand Down Expand Up @@ -43,6 +43,10 @@ SKIP_PACK=true RUNTIME_PARAM=18 CASE_PARAM=container-esm ./integration_tests_loc

# Force amd64 images instead of arm64
PLATFORM=linux/amd64 ./integration_tests_local/run.sh

# Bypass a broken local VM host-port forward without changing the function.
# Runs the same HTTP requests using curl inside the target container.
RIE_HTTP_TRANSPORT=container RUNTIME_PARAM=22 CASE_PARAM=manual-timeout ./integration_tests_local/run.sh
```

CI runs the complete runtime/case matrix on native `linux/amd64` and
Expand All @@ -69,6 +73,8 @@ The case names are:
| `manual-send-metrics` | manual wrap calling `sendDistributionMetric` inside and outside the handler; per-event return values |
| `manual-process-input` | manual wrap with userland `dd-trace` init reading the active span; per-event return values |
| `manual-callback` | manual wrap of a callback-style `(event, context, callback)` handler; pins the `promisifiedHandler` seam end to end (the migration spike broke exactly this) |
| `manual-timeout` | explicit userland tracer init, then manual wrap; impending-timeout error on the invocation and `killAll()` flushing an unfinished child before RIE terminates the runtime |
| `cjs-timeout` | the same timeout contract through `DD_LAMBDA_HANDLER` and the npm redirect entrypoint, exercising the raw-handler hook also used by layers |
| `manual-metrics-only` | `DD_TRACE_ENABLED=false` (metrics-only customers): enhanced + custom metrics still flush, no `aws.lambda` span, no trace JSON, no `dd.trace_id` log correlation |
| `cjs-capture-payload` | `DD_CAPTURE_LAMBDA_PAYLOAD=true` in redirect mode; span meta gains `function.request` / `function.response` with the captured payloads |
| `cjs-http-requests` | downstream HTTP calls against a hermetic mock server in redirect mode; asserts injected `x-datadog-*`/`traceparent` headers and log injection via dd-trace's http plugin |
Expand Down Expand Up @@ -112,6 +118,7 @@ snapshots/logs/<case>.log # shared across runtimes
snapshots/return_values/default.json # return mode "default": every event, every case
snapshots/return_values/<case>.json # return mode "case": one payload for all 9 events
snapshots/return_values/<case>_<event>.json # return mode "per-event": payload embeds event data
snapshots/return_values/<timeout-case>.txt # RIE's plain-text timeout response
```

The normalized logs of most cases are identical across all five runtimes, so
Expand Down Expand Up @@ -159,10 +166,11 @@ filter to absorb it would be invisible. Current overrides:
assertions — the proactive-initialization markers — are grep-checked on
the raw logs and are identical on every runtime.

In update mode, a leg that disagrees with an existing shared golden **fails**
instead of overwriting it — otherwise the last runtime to run would silently
define the expectation for all of them. To capture a genuine per-runtime
divergence, `touch` the override file first so the write targets it.
In update mode, the first leg writes the shared golden. Later legs in the
same run **fail** if they disagree instead of overwriting it — otherwise the
last runtime to run would silently define the expectation for all of them.
To capture a genuine per-runtime divergence, `touch` the override file first
so the write targets it.

## The mock HTTP server (cjs-http-requests, manual-http-requests)

Expand All @@ -180,6 +188,94 @@ while `manual-http-requests` is manual-wrapped with no tracer (TraceListener
falls back to the library's own `patchHttp`). See "Known emulation gaps" for
what the manual case cannot pin locally.

## Impending timeouts (manual-timeout, cjs-timeout)

These cases exercise both pre-migration dd-trace hook paths: manual
`datadog(handler)` wrapping and the `DD_LAMBDA_HANDLER` redirect. The manual
fixture initializes dd-trace **before** importing the shim; importing the shim
alone does not initialize tracing or install the timeout monitor.

The handler opens a `timeout.unfinished` child span and waits 60 seconds.
`AWS_LAMBDA_FUNCTION_TIMEOUT=5` gives the invocation a real RIE deadline, and
`DD_APM_FLUSH_DEADLINE_MILLISECONDS=3500` makes dd-trace flush roughly 1.5
seconds into the invocation (less the init time). RIE then kills the runtime
at five seconds. All nine input events are exercised, with a fresh runtime
after each timeout. The two cases add about 90 seconds per runtime leg.

RIE v1.36 returns HTTP 200 with the **plain text**
`Task timed out after 5.00 seconds`, not Lambda's JSON error envelope.
Consequently, these return goldens use `.txt`. Completion is gated on REPORT,
timeout-reset, and SIGKILL records; a killed runtime never emits INVOKE RTDONE.
The HTTP client is bounded to 15 seconds so a broken deadline cannot hang CI.

Before normalization or snapshot creation, `check-timeout-logs.js` reads all
trace payloads and asserts for every raw request ID:

- exactly one `aws.lambda` span across all payloads, with `error=1`,
`error.type=Impending Timeout`, and the expected error message;
- exactly one unfinished child in that invocation's trace, with the invocation
as its parent and no error on the child;
- both spans were exported before REPORT, and the invocation span finished
within 2.5 seconds (the configured 1.5-second guard plus scheduling headroom,
which also rejects silently falling back to the default 100ms flush deadline);
- RIE actually reset and killed the runtime once per invocation.

This catches duplicate invocation spans even when they appear in separate
traces, and prevents a metrics-only run from becoming a passing golden. The
helper preserves trace payloads unchanged. It normalizes only volatile IDs
and timestamps in RIE timeout diagnostics, including Go's varying log-field
order. Every diagnostic record and severity remains in the snapshot; the
shared AWS/RIE normalizer is unchanged.

Run the helper's regression tests independently with:

```bash
node --test integration_tests_local/check-timeout-logs.test.js
```

### Golden provenance

The timeout goldens were recaptured after merging main, from pre-migration
library commit `291fd14e9b8c54b94ba5b57998f726231839dc92`
(`datadog-lambda-js` 12.143.0), with no additional production-source changes.
Both cases used RIE v1.36 on `linux/arm64`, across Node 18/20/22/24/26. The
fixture runner installed dd-trace 5.126.0 on Node 18/20 and the lockfile-resolved
6.15.0 on Node 22/24/26. All five runtimes produced the same shared goldens;
no runtime-specific timeout overrides were needed.

Both cases passed a comparison-only rerun across all five runtimes (90
invocations), leaving all four timeout snapshot files byte-for-byte unchanged.

The existing `manual-throw-error` and `container-cjs` goldens also passed
unchanged on Node 22 through the same transport. The checker has nine
regression tests.

The previous files recorded the older `cf751a76` baseline with dd-trace
5.105.0 on every runtime. Those snapshots stopped matching after the main
merge: the current tracer omits empty `links: []` fields, and the shim resolves
the loaded tracer's version at runtime instead of recording an empty
`dd_trace` tag. The recapture changes only those fields and ordinary RIE
record ordering under the existing line-order comparison. Timeout error
decoration, span counts, parent/child relationships, and flush checks remain
unchanged. Neither the raw checker nor the shared normalizer was loosened.

When intentionally recapturing an existing shared golden, first review why
the baseline changed. The current runner lets the first leg overwrite a shared
golden in `UPDATE_SNAPSHOTS=true` mode and requires later legs in that run to
agree. Unlike the older capture baseline, it no longer requires deleting the
existing golden first.

The local capture used `RIE_HTTP_TRANSPORT=container` because Colima's
published host ports were unreachable. RIE was reachable over IPv4 inside
the containers, so this was not an IPv6-only RIE listener. This transport
does not alter the handler, tracer, invocation body, or RIE timeout.

These are L2 emulator goldens, not evidence of real AWS termination behavior
or layer packaging. The redirect case covers the raw-handler hook used by
layers; real AWS timeout behavior still needs L3 coverage. The CI workflow is
configured to compare these goldens on native amd64 and arm64; the local capture
used arm64.

## Proactive initialization (cjs-proactive-init)

The library stamps `initTime = Date.now()` at wrapper-module load
Expand Down Expand Up @@ -209,6 +305,33 @@ the three markers:

## Pinned runtime infrastructure

All five Lambda base images are pinned to multi-architecture manifest digests
in `run.sh`'s `lambda_node_image_tag()`. The same reference is used by the CJS,
ESM, layer, and mock-server fixtures, with `PLATFORM` selecting amd64 or arm64.
The pins come from [CI run 36168116285](https://github.com/DataDog/datadog-lambda-js/actions/runs/36168116285)
on September 25, 2026. A warm local Docker cache and a clean CI runner must not
silently test different runtime releases under the same major-version tag.

That discrepancy caused two baseline changes with no library-source changes:
the newer Node 22/24 managed runtime emits a structured
`runtime_worker_pool_initializing` DEBUG record, and Node 24 now includes
`requestId` in its thrown-error response. The corresponding proactive-init log
goldens and Node 24 error-return golden were recaptured from the pre-migration
library at `8785aeee`, using the pinned images on arm64. The runtime record is
preserved in full, including `workerCount: 4` (the harness specifies `--cpus 4`)
and `executionEnvironmentMaxConcurrency: 1`; the response retains `requestId`
with its existing volatile-value normalization. The shared normalizer and the
three raw proactive-init assertions are unchanged.

After recapture, all 18 cases passed in comparison-only mode on both Node 22
and Node 24 / arm64 (324 invocations). The three refreshed expectations kept
the same hashes, and the timeout goldens were not changed by this refresh.

To update a runtime, change its digest in `lambda_node_image_tag()`, inspect
the runtime differences, and recapture only the affected expectations before
running comparison-only tests on both architectures. Do not remove runtime
records to make a new base image match an older golden.

The harness pins AWS Runtime Interface Emulator (RIE) `v1.36` and verifies the
cached binary on every run before mounting it into a container:

Expand All @@ -224,7 +347,7 @@ Node 26 is still preview-only in ECR Public: the bare
`public.ecr.aws/lambda/nodejs:26` tag does not exist. The logical runtime stays
`26` for image names, function names, and snapshot paths, while the Docker
base-image build argument maps to the dated multi-arch tag
`26-preview.2026.08.21.22`.
`26-preview.2026.08.21.22` plus its manifest digest.

Node 26 is a strict leg like every other; where its preview runtime
genuinely diverges (error stack frames, warning emission) it carries
Expand All @@ -248,6 +371,8 @@ under test. A base-image change must be reviewed, not hidden by normalization.
Reads stdin, writes stdout; honors `RUN_ID` for optional per-run ID stripping.
- `prepare-layer.js` — assembles the layer fixture's build context from the
repo build, mirroring the release Dockerfile's `/opt` layout
- `check-timeout-logs.js` — validates raw timeout traces and normalizes only
the timeout-specific RIE diagnostics before the shared normalizer
- `bin/` — downloaded RIE binary (gitignored)
- `snapshots/logs/` — normalized log snapshots, shared per case across
runtimes, with optional `<case>_node<major>.log` overrides
Expand Down
93 changes: 93 additions & 0 deletions integration_tests_local/check-timeout-logs.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,93 @@
"use strict";

const assert = require("node:assert/strict");
const fs = require("node:fs");

// Check raw identities and complete trace payloads before the shared golden
// normalizer removes IDs or the runner sorts lines. A "some trace matches"
// assertion cannot catch two invocation spans exported in different payloads.
const expected = Number(process.argv[2]);
assert.ok(Number.isInteger(expected) && expected > 0, "expected invocation count is required");
const raw = fs.readFileSync(0, "utf8");
const lines = raw.trimEnd().split("\n");
const starts = new Map();
const reports = new Map();
const spans = [];

for (const [index, line] of lines.entries()) {
const start = /^START RequestId: (\S+)/.exec(line);
const report = /^REPORT RequestId: (\S+)/.exec(line);
if (start) {
assert.ok(!starts.has(start[1]), "duplicate START request ID");
starts.set(start[1], index);
}
if (report) {
assert.ok(!reports.has(report[1]), "duplicate REPORT request ID");
reports.set(report[1], index);
}
let record;
try {
record = JSON.parse(line);
} catch {
continue;
}
if (Array.isArray(record.traces)) {
for (const trace of record.traces) {
for (const span of trace) spans.push({ span, index });
}
}
}

assert.equal(starts.size, expected, "START count");
assert.equal(reports.size, expected, "REPORT count");
assert.equal(lines.filter((line) => line.includes("Reset initiated: Timeout")).length, expected, "timeout resets");
assert.equal(lines.filter((line) => line.includes("Sending SIGKILL to runtime-")).length, expected, "runtime kills");

const invocations = spans.filter(({ span }) => span.name === "aws.lambda");
const children = spans.filter(({ span }) => span.name === "timeout.unfinished");
assert.equal(invocations.length, expected, "exactly one Lambda span per invocation across all trace payloads");
assert.equal(children.length, expected, "killAll must flush every unfinished child");
for (const [requestId, startIndex] of starts) {
const matching = invocations.filter(({ span }) => span.meta?.request_id === requestId);
assert.equal(matching.length, 1, `Lambda span count for ${requestId}`);
const { span, index } = matching[0];
assert.equal(span.error, 1, "invocation must be marked as an error");
assert.equal(span.meta["error.type"], "Impending Timeout");
assert.equal(span.meta["error.message"], "Datadog detected an impending timeout");
assert.ok(index > startIndex && index < reports.get(requestId), "span exported before runtime timeout REPORT");
// The configured guard fires ~1.5s in, allowing 1s of scheduling overhead.
// Expected around 1.5s; allow generous tolerance while rejecting immediate firing.
assert.ok(
span.duration >= 0.5e9 && span.duration < 2.5e9,
`span must honor the 3500ms flush deadline: got ${span.duration / 1e9}s`,
);
const matchingChildren = children.filter(
({ span: child }) => child.trace_id === span.trace_id && child.parent_id === span.span_id,
);
assert.equal(matchingChildren.length, 1, "unfinished child must stay in its invocation's trace");
const child = matchingChildren[0];
assert.equal(child.span.error, 0, "timeout must decorate the invocation rather than the child");
assert.ok(
child.index > startIndex && child.index < reports.get(requestId),
"child exported before runtime timeout REPORT",
);
}

// Only RIE's new timeout diagnostics need extra normalization. Keep every
// record, severity, and error value; replace volatile runtime/PID/request IDs
// and canonicalize Go's nondeterministic order of these two log fields.
process.stdout.write(
lines
.map((line) => {
if (!/^\d{2} \w{3} \d{4} .*\[(?:INFO|ERROR|WARNING)\] \(rapid\)/.test(line)) return line;
return line
.replace(/^\d{2} \w{3} \d{4} \d{2}:\d{2}:\d{2},\d{3} /, "XXXX ")
.replace(/InvokeID=[0-9a-f-]+/g, "InvokeID=XXXX")
.replace(/runtime-\d+\(\d+\)/g, "runtime-XX(XX)")
.replace(
"Invoke failed error=errResetReceived InvokeID=XXXX",
"Invoke failed InvokeID=XXXX error=errResetReceived",
);
})
.join("\n") + "\n",
);
Loading
Loading