diff --git a/integration_tests_local/README.md b/integration_tests_local/README.md index 53e32b5a..c0079caf 100644 --- a/integration_tests_local/README.md +++ b/integration_tests_local/README.md @@ -6,9 +6,9 @@ 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), invokes them with the same input events as the AWS-based suite, captures -logs from `docker logs`, normalizes them with `./normalize.sh` — the AWS -suite's filter chain plus documented RIE-specific handling, not an identical -copy — and diffs them against **local** snapshots in `./snapshots/`. +logs from `docker logs`, normalizes them with the `rie` mode of +`../scripts/normalize_integration_logs.sh`, and diffs them against **local** +snapshots in `./snapshots/`. The case set is deliberately at least as wide as the AWS-based suite (`integration_tests/serverless.yml`): every behavior the old suite pinned @@ -224,16 +224,15 @@ genuinely diverges (error stack frames, warning emission) it carries When AWS publishes the bare Node 26 GA image, swap the pinned tag and re-run. If GA output diverges further, add `*_node26` overrides captured from the -pinned pre-migration ref rather than absorbing the difference into -`normalize.sh` — the oracle is tied to the implementation under test, and a -base-image change must be reviewed, not hidden by normalization. +pinned pre-migration ref. Do not absorb the difference into the shared +integration-log normalizer because the oracle is tied to the implementation +under test. A base-image change must be reviewed, not hidden by normalization. ## Files - `run.sh` — the runner (build images, run under RIE, invoke, diff snapshots) -- `normalize.sh` — the local log-normalization pipeline, based on the AWS - suite's filters with documented RIE-specific handling. Reads stdin, writes - stdout; honors `RUN_ID` for optional per-run ID stripping. +- `../scripts/normalize_integration_logs.sh` — the shared AWS/RIE log normalizer. + 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 - `bin/` — downloaded RIE binary (gitignored) diff --git a/integration_tests_local/normalize.sh b/integration_tests_local/normalize.sh deleted file mode 100755 index c7f1ff6d..00000000 --- a/integration_tests_local/normalize.sh +++ /dev/null @@ -1,110 +0,0 @@ -#!/bin/bash - -# Local log-normalization pipeline for integration test snapshots. -# -# This is based on the filter chain used by scripts/run_integration_tests.sh -# to replace invocation-specific data (timestamps, IDs, durations, ...) with -# XXXX before diffing logs against snapshots. Local-only RIE filters and -# deterministic cold-start assertions are documented below. -# -# Usage: -# some-log-producer | ./normalize.sh -# RUN_ID=abcdef12 ./normalize.sh < raw.log > normalized.log -# -# Reads from stdin, writes to stdout. -# Optional env: -# RUN_ID - random per-run ID embedded in deployed function names; stripped -# to XXXX when set (AWS suite only; the local harness uses static -# function names and leaves this unset). - -set -e - -script_path=${BASH_SOURCE[0]} -local_dir=$(dirname "$script_path") -repo_dir=$(dirname "$local_dir") - -# An empty Perl program is a pass-through when RUN_ID is unset. -run_id_filter='' -if [ -n "$RUN_ID" ]; then - run_id_filter="s/${RUN_ID}/XXXX/g" -fi - -node "$repo_dir/integration_tests/parse-json.js" | - # Filter serverless cli errors - sed '/Serverless: Recoverable error occurred/d' | - # Normalize Lambda runtime report logs - perl -p -e 's/(RequestId|TraceId|init|SegmentId|Duration|Memory Used|"e"):( )?[a-z0-9\.\-]+/\1:\2XXXX/g' | - # Node.js 26 preview and container-image runtimes emit extra platform noise. - sed '/preview runtime version and should not be used for production workloads/d' | - sed '/^INIT_REPORT /d' | - sed '/DEP0205.*module\.register()/d' | - sed '/node --trace-deprecation.*where the warning was created/d' | - # Normalize DD APM headers and AWS account ID - perl -p -e "s/(x-datadog-parent-id:|x-datadog-trace-id:|account_id:)[0-9]+/\1XXXX/g" | - # Same headers as echoed by the http-requests fixture's mock server — - # JSON.stringify output, i.e. quoted with no space after the colon — - # plus the W3C traceparent/tracestate pair it also echoes. - perl -p -e 's/"(x-datadog-trace-id|x-datadog-parent-id)":"[0-9]+"/"\1":"XXXX"/g' | - perl -p -e 's/"traceparent":"[0-9a-f-]+"/"traceparent":"XXXX"/g' | - perl -p -e 's/"tracestate":"[^"]*"/"tracestate":"XXXX"/g' | - # Strip API key from logged requests - perl -p -e "s/(api_key=|'api_key': ')[a-z0-9\.\-]+/\1XXXX/g" | - # Normalize log timestamps - perl -p -e "s/[0-9]{4}\-[0-9]{2}\-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]+( \(\-?\+?[0-9:]+\))?/XXXX-XX-XX XX:XX:XX.XXX/" | - # Same for the ISO8601-with-T format the RIC uses on ERROR lines under RIE - # (e.g. "2026-08-28T04:00:26.774Z\t\tERROR\tInvoke Error ...") - perl -p -e "s/[0-9]{4}\-[0-9]{2}\-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]+Z/XXXX-XX-XXTXX:XX:XX.XXXZ/" | - # Managed-instances (proactive-init case) structured logs: per-invocation - # request ids, and the overflow value in Node's TimeoutOverflowWarning, - # which is derived from a wall-clock deadline and varies run to run. - perl -p -e 's/"requestId": "[0-9a-f-]+"/"requestId": "XXXX"/g' | - # Same id in the compact JSON the preview RIC uses on Invoke Error lines. - perl -p -e 's/"requestId":"[0-9a-f-]+"/"requestId":"XXXX"/g' | - perl -p -e 's/TimeoutOverflowWarning: [0-9]+/TimeoutOverflowWarning: XXXX/g' | - # Node appends its once-per-process "trace-warnings" hint to whichever - # warning happens to be emitted first — which one is racy (and differs - # between amd64 CI and arm64 local runs). Drop the hint in both its - # JSON-embedded (\n literal) and standalone-line forms. - perl -p -e 's/\\n\(Use `node --trace-warnings \.\.\.` to show where the warning was created\)//g' | - sed '/^(Use `node --trace-warnings \.\.\.` to show where the warning was created)$/d' | - # Pid in Node's "(node:NN)" warning prefix varies with process layout. - perl -p -e 's/\(node:[0-9]+\)/(node:XX)/g' | - # Normalize DD trace ID injection - perl -p -e "s/(dd\.trace_id=)[0-9]+ (dd\.span_id=)[0-9]+/\1XXXX \2XXXX/" | - # Normalize execution ID in logs prefix - perl -p -e $'s/[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\t/XXXX-XXXX-XXXX-XXXX-XXXX\t/' | - # Normalize minor package version tag so that these snapshots aren't broken on version bumps - perl -p -e "s/(dd_lambda_layer:datadog-nodev[0-9]+\.)[0-9]+\.[0-9]+/\1XX\.X/g" | - perl -p -e 's/"(span_id|apiid|runtime-id|record_ids|parent_id|trace_id|start|duration|tcp\.local\.address|tcp\.local\.port|dns\.address|request_id|function_arn|x-datadog-trace-id|x-datadog-parent-id|datadog_lambda|dd_trace|process_id)":\ ("?)[a-zA-Z0-9\.:\-]+("?)/"\1":\2XXXX\3/g' | - # Resolved IP of the mock-http container: varies with whichever /16 Docker's address pool hands the per-run network. - perl -p -e 's/"dns\.addresses": "[^"]*"/"dns.addresses": "XXXX"/g' | - # Strip out run ID (from function name, resource, etc.) - perl -p -e "$run_id_filter" | - # Normalize line numbers in stack traces - perl -p -e 's/(.js:)[0-9]*:[0-9]*/\1XXX:XXX/g' | - # Preserve stable span meta and metrics; volatile values are normalized above. - # Normalize enhanced metric datadog_lambda tag - perl -p -e "s/(datadog_lambda:v)[0-9\.]+/\1X.X.X/g" | - # Normalize lookup resource - perl -p -e "s/(\"resource\":\"169.)[0-9\.]+/\1X.X.X/g" | - # Normalize Axios version - perl -p -e "s/User-Agent:axios\/\d+\.\d+\.\d+/User-Agent:axios\/X\.X\.X/g" | - # Remove init start line - perl -p -e "s/INIT_START.*//g" | - # Proactive initialization is platform scheduling, not code behavior. - # Keep cold_start to cover the deterministic local cold-to-warm transition. - sed '/proactive_initialization/d' | - perl -p -e 's/ \(init: [^)]*\)//g' | - # Normalize RIE platform log lines (local harness only; no-op on AWS logs): - # "28 Jul 2026 19:42:34,536 [INFO] (rapid) ..." timestamps, request ids, - # and init/invoke durations vary run to run - perl -p -e 's/^[0-9]{2} \w{3} [0-9]{4} [0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3} (\[INFO\] \(rapid\))/XXXX \1/' | - # Managed-instances supervisor line embeds a container pid: pid=NN. - perl -p -e 's/(LocalProcessSupervisor\.Exec pid=)[0-9]+/\1XX/g' | - perl -p -e 's/(requestId: )[0-9a-f-]+/\1XXXX/g' | - perl -p -e 's/(duration(Ms)?: )[0-9.]+/\1XXXX/g' | - sed -E "s/(tracestate\:)([A-Za-z0-9\-\=\:\;].+)/\1XXX/g" | - sed -E "s/(\"_dd.p.tid\"\: \")[a-z0-9\.\-]+/\1XXXX/g" | - sed -E "s/(_dd.p.tid=)[a-z0-9\.\-]+/\1XXXX/g" | - # Remove RIE's trailing REPORT tab without changing application output. - sed -E '/^REPORT RequestId:/s/[[:blank:]]+$//' diff --git a/integration_tests_local/run.sh b/integration_tests_local/run.sh index 1ebe3a58..d821d1b9 100755 --- a/integration_tests_local/run.sh +++ b/integration_tests_local/run.sh @@ -4,7 +4,7 @@ # # Runs the test cases below against the AWS Runtime Interface Emulator (RIE) # — no AWS account needed. Logs are captured from `docker logs`, normalized -# with ./normalize.sh, and diffed against LOCAL snapshots in ./snapshots/ +# with the `rie` mode of scripts/normalize_integration_logs.sh, and diffed against LOCAL snapshots in ./snapshots/ # (not integration_tests/snapshots/). # # The case set is deliberately at least as wide as the AWS-based suite in @@ -483,7 +483,7 @@ function compare_snapshot() { local diff_status if [ "$sort_lines" = true ]; then - # Preserve normalized whitespace; normalize.sh removes RIE's REPORT tab. + # Preserve normalized whitespace; the shared normalizer removes RIE's REPORT tab. diff_output=$(printf '%s\n' "$actual" | LC_ALL=C sort | diff - <(LC_ALL=C sort "$snapshot_path")) else diff_output=$(printf '%s\n' "$actual" | diff - "$snapshot_path") @@ -775,7 +775,7 @@ for node_version in "${RUNTIMES[@]}"; do continue fi - # Proactive initialization is platform scheduling, so normalize.sh + # Proactive initialization is platform scheduling, so the shared normalizer # drops the markers. For the dedicated case we assert them against the # raw log before normalization, which keeps the coverage without # weakening the shared pipeline. @@ -790,7 +790,7 @@ for node_version in "${RUNTIMES[@]}"; do done fi - logs=$(printf '%s\n' "$raw_logs" | "$local_dir/normalize.sh") + logs=$(printf '%s\n' "$raw_logs" | "$repo_dir/scripts/normalize_integration_logs.sh" rie) # `runtime:nodejsNN.x` is the only genuinely runtime-specific line in # the whole log — everything else is identical across 18/20/22/24/26. @@ -813,7 +813,7 @@ for node_version in "${RUNTIMES[@]}"; do # Same assert-then-collapse for the dd_lambda_layer tag (emitted by the # manual-wrap cases): the node major in the tag must match the runtime - # under test. normalize.sh already collapses minor/patch to XX.X; + # under test. The shared normalizer already collapses minor/patch to XX.X; # after this guard passes, the major collapses to XX as well, so the # shared golden reads datadog-nodevXX.XX.X. layer_majors=$(printf '%s\n' "$logs" | grep -o 'dd_lambda_layer:datadog-nodev[0-9]*' | sed 's/.*datadog-nodev//' | sort -u || true) diff --git a/scripts/normalize_integration_logs.sh b/scripts/normalize_integration_logs.sh new file mode 100755 index 00000000..5128ff83 --- /dev/null +++ b/scripts/normalize_integration_logs.sh @@ -0,0 +1,93 @@ +#!/bin/bash + +set -eo pipefail + +if [ "$#" -lt 1 ] || [ "$#" -gt 2 ]; then + echo "Usage: $0 [raw|formatted]" >&2 + exit 2 +fi + +platform=$1 +case "$platform" in + aws) + cold_start_filter="s/(\"cold_start\":[[:space:]]*)\"(?:true|false)\"/\$1\"XXXX\"/g" + cold_start_filter+="; s/cold_start:(?:true|false)/cold_start:XXXX/g" + leading_blank_filter='/./,$!d' + ;; + rie) + cold_start_filter='' + leading_blank_filter='' + ;; + *) + echo "Unsupported integration-test platform: $platform" >&2 + exit 2 + ;; +esac + +input_format=${2:-raw} +case "$input_format" in + raw|formatted) ;; + *) + echo "Unsupported integration-test log format: $input_format" >&2 + exit 2 + ;; +esac + +timestamp_filter="s/[0-9]{4}\\-[0-9]{2}\\-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\\.[0-9]+" +timestamp_filter+="( \\(\\-?\\+?[0-9:]+\\))?/XXXX-XX-XX XX:XX:XX.XXX/" +volatile_value_filter="s/\"(span_id|apiid|runtime-id|record_ids|parent_id|trace_id|start|duration" +volatile_value_filter+="|tcp\\.local\\.address|tcp\\.local\\.port|dns\\.address|request_id|function_arn" +volatile_value_filter+="|x-datadog-trace-id|x-datadog-parent-id|datadog_lambda|dd_trace|process_id)\"" +volatile_value_filter+=": (\"?)[a-zA-Z0-9\\.:\\-]+(\"?)/\"\$1\":\$2XXXX\$3/g" + +script_path=${BASH_SOURCE[0]} +scripts_dir=$(dirname "$script_path") +repo_dir=$(dirname "$scripts_dir") + +if [ "$input_format" = formatted ]; then + cat +else + node "$repo_dir/integration_tests/parse-json.js" +fi | + sed '/Serverless: Recoverable error occurred/d' | + perl -p -e 's/(RequestId|TraceId|init|SegmentId|Duration|Memory Used|"e"):( )?[a-z0-9\.\-]+/\1:\2XXXX/g' | + sed '/preview runtime version and should not be used for production workloads/d' | + sed '/^INIT_REPORT /d' | + sed '/DEP0205.*module\.register()/d' | + sed '/node --trace-deprecation.*where the warning was created/d' | + perl -p -e 's/(x-datadog-parent-id:|x-datadog-trace-id:|account_id:)[0-9]+/$1XXXX/g' | + perl -p -e 's/"(x-datadog-trace-id|x-datadog-parent-id)":"[0-9]+"/"$1":"XXXX"/g' | + perl -p -e 's/"traceparent":"[0-9a-f-]+"/"traceparent":"XXXX"/g' | + perl -p -e 's/"tracestate":"[^"]*"/"tracestate":"XXXX"/g' | + perl -p -e "s/(api_key=|'api_key': ')[a-z0-9\.\-]+/\1XXXX/g" | + perl -p -e "$timestamp_filter" | + perl -p -e 's/[0-9]{4}\-[0-9]{2}\-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]+Z/XXXX-XX-XXTXX:XX:XX.XXXZ/' | + perl -p -e 's/"requestId": "[0-9a-f-]+"/"requestId": "XXXX"/g' | + perl -p -e 's/"requestId":"[0-9a-f-]+"/"requestId":"XXXX"/g' | + perl -p -e 's/TimeoutOverflowWarning: [0-9]+/TimeoutOverflowWarning: XXXX/g' | + perl -p -e 's/\\n\(Use `node --trace-warnings \.\.\.` to show where the warning was created\)//g' | + sed '/^(Use `node --trace-warnings \.\.\.` to show where the warning was created)$/d' | + perl -p -e 's/\(node:[0-9]+\)/(node:XX)/g' | + perl -p -e 's/(dd\.trace_id=)[0-9]+ (dd\.span_id=)[0-9]+/$1XXXX $2XXXX/' | + perl -p -e $'s/[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\t/XXXX-XXXX-XXXX-XXXX-XXXX\t/' | + perl -p -e 's/(dd_lambda_layer:datadog-nodev[0-9]+\.)[0-9]+\.[0-9]+/$1XX.X/g' | + perl -p -e "$volatile_value_filter" | + perl -p -e 's/"dns\.addresses": "[^"]*"/"dns.addresses": "XXXX"/g' | + RUN_ID="${RUN_ID:-}" perl -p -e 's/\Q$ENV{RUN_ID}\E/XXXX/g if length $ENV{RUN_ID}' | + perl -p -e 's/(.js:)[0-9]*:[0-9]*/$1XXX:XXX/g' | + perl -p -e 's/(datadog_lambda:v)[0-9\.]+/$1X.X.X/g' | + perl -p -e 's/("resource":"169.)[0-9\.]+/$1X.X.X/g' | + perl -p -e 's/User-Agent:axios\/\d+\.\d+\.\d+/User-Agent:axios\/X.X.X/g' | + sed '/INIT_START Runtime Version:/d' | + sed "$leading_blank_filter" | + sed -E '/^[[:space:]]*"proactive_initialization(" *:|:true")/d' | + perl -p -e "$cold_start_filter" | + perl -p -e 's/ \(init: [^)]*\)//g' | + perl -p -e 's/^[0-9]{2} \w{3} [0-9]{4} [0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3} (\[INFO\] \(rapid\))/XXXX $1/' | + perl -p -e 's/(LocalProcessSupervisor\.Exec pid=)[0-9]+/$1XX/g' | + perl -p -e 's/(requestId: )[0-9a-f-]+/$1XXXX/g' | + perl -p -e 's/(duration(Ms)?: )[0-9.]+/$1XXXX/g' | + sed -E 's/(tracestate\:)([A-Za-z0-9\-\=\:\;].+)/\1XXX/g' | + sed -E 's/("_dd.p.tid"\: ")[a-z0-9\.\-]+/\1XXXX/g' | + sed -E 's/(_dd.p.tid=)[a-z0-9\.\-]+/\1XXXX/g' | + sed -E '/^REPORT RequestId:/s/[[:blank:]]+$//' diff --git a/scripts/run_integration_tests.sh b/scripts/run_integration_tests.sh index f052060b..fe35b564 100755 --- a/scripts/run_integration_tests.sh +++ b/scripts/run_integration_tests.sh @@ -27,15 +27,18 @@ export BUILDX_NO_DEFAULT_ATTESTATIONS=1 ALL_LAMBDA_HANDLERS=("async-metrics" "esm" "sync-metrics" "http-requests" "process-input-traced" "throw-error-traced" "status-code-500s" "container-cjs" "container-esm") ZIP_LAMBDA_HANDLERS=("async-metrics" "esm" "sync-metrics" "http-requests" "process-input-traced" "throw-error-traced" "status-code-500s") -LOGS_WAIT_SECONDS=20 +LOG_FETCH_ATTEMPTS=10 +LOG_FETCH_INTERVAL_SECONDS=10 -script_path=${BASH_SOURCE[0]} -scripts_dir=$(dirname $script_path) -repo_dir=$(dirname $scripts_dir) +scripts_dir=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) +repo_dir=$(dirname "$scripts_dir") cwd=$(pwd) integration_tests_dir="$repo_dir/integration_tests" +# shellcheck source=scripts/wait_for_complete_logs.sh +source "$scripts_dir/wait_for_complete_logs.sh" + script_utc_start_time=$(date -u +"%Y%m%dT%H%M%S") mismatch_found=false @@ -197,103 +200,50 @@ nodejs version : ${!nodejs_version} and run id : ${!run_id}" done done done -set -e - -echo "Sleeping $LOGS_WAIT_SECONDS seconds to wait for logs to appear in CloudWatch..." -sleep $LOGS_WAIT_SECONDS - set +e # Don't exit this script if there is a diff or the logs endpoint fails echo "Fetching logs for invocations and comparing to snapshots" +expected_completion_count=${#input_event_files[@]} for handler_name in "${LAMBDA_HANDLERS[@]}"; do for parameters_set in "${PARAMETERS_SETS[@]}"; do function_name="${handler_name}_node" function_snapshot_path="./snapshots/logs/${handler_name}_${parameters_set}.log" - unstripped_path="./snapshots/logs/${handler_name}_${parameters_set}.log.unstripped" serverless_runtime=$parameters_set[0] nodejs_version=$parameters_set[1] run_id=$parameters_set[2] - # Fetch logs with serverless cli, retrying to avoid AWS account-wide rate limit error - retry_counter=0 - while [ $retry_counter -lt 10 ]; do - raw_logs=$(run_serverless logs --stage ${!run_id} -f $function_name --startTime $script_utc_start_time) - fetch_logs_exit_code=$? - if [ $fetch_logs_exit_code -eq 1 ]; then - echo "Retrying fetch logs for $function_name..." - retry_counter=$(($retry_counter + 1)) - sleep 10 - continue - fi - break - done - - if [ $retry_counter -eq 9 ]; then - echo "FAILURE: Could not retrieve logs for $function_name" - echo "Error from final attempt to retrieve logs:" - echo $raw_logs - - exit 1 + if ! raw_logs=$(wait_for_complete_logs \ + "$expected_completion_count" \ + "$LOG_FETCH_ATTEMPTS" \ + "$LOG_FETCH_INTERVAL_SECONDS" \ + run_serverless logs --stage "${!run_id}" -f "$function_name" --startTime "$script_utc_start_time"); then + mismatch_found=true + continue fi + if ! logs=$(printf '%s\n' "$raw_logs" | \ + RUN_ID="${!run_id}" "$scripts_dir/normalize_integration_logs.sh" aws); then + echo "FAILURE: Could not normalize logs for $function_name" >&2 + mismatch_found=true + continue + fi - # Replace invocation-specific data like timestamps and IDs with XXXX to normalize logs across executions - logs=$( - echo "$raw_logs" | - node parse-json.js | - # Filter serverless cli errors - sed '/Serverless: Recoverable error occurred/d' | - # Normalize Lambda runtime report logs - perl -p -e 's/(RequestId|TraceId|init|SegmentId|Duration|Memory Used|"e"):( )?[a-z0-9\.\-]+/\1:\2XXXX/g' | - # Drop init duration from END lines; cold starts sometimes include it, warm starts do not. - perl -p -e 's/ \(init: XXXX ms\)//g' | - # Node.js 26 preview and container-image runtimes emit extra platform noise. - sed '/preview runtime version and should not be used for production workloads/d' | - sed '/^INIT_REPORT /d' | - sed '/DEP0205.*module\.register()/d' | - sed '/node --trace-deprecation.*where the warning was created/d' | - # Normalize DD APM headers and AWS account ID - perl -p -e "s/(x-datadog-parent-id:|x-datadog-trace-id:|account_id:)[0-9]+/\1XXXX/g" | - # Strip API key from logged requests - perl -p -e "s/(api_key=|'api_key': ')[a-z0-9\.\-]+/\1XXXX/g" | - # Normalize log timestamps - perl -p -e "s/[0-9]{4}\-[0-9]{2}\-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]+( \(\-?\+?[0-9:]+\))?/XXXX-XX-XX XX:XX:XX.XXX/" | - # Normalize DD trace ID injection - perl -p -e "s/(dd\.trace_id=)[0-9]+ (dd\.span_id=)[0-9]+/\1XXXX \2XXXX/" | - # Normalize execution ID in logs prefix - perl -p -e $'s/[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\-[0-9a-z]+\t/XXXX-XXXX-XXXX-XXXX-XXXX\t/' | - # Normalize minor package version tag so that these snapshots aren't broken on version bumps - perl -p -e "s/(dd_lambda_layer:datadog-nodev[0-9]+\.)[0-9]+\.[0-9]+/\1XX\.X/g" | - perl -p -e 's/"(span_id|apiid|runtime-id|record_ids|parent_id|trace_id|start|duration|tcp\.local\.address|tcp\.local\.port|dns\.address|request_id|function_arn|x-datadog-trace-id|x-datadog-parent-id|datadog_lambda|dd_trace|process_id)":\ ("?)[a-zA-Z0-9\.:\-]+("?)/"\1":\2XXXX\3/g' | - # Strip out run ID (from function name, resource, etc.) - perl -p -e "s/${!run_id}/XXXX/g" | - # Normalize line numbers in stack traces - perl -p -e 's/(.js:)[0-9]*:[0-9]*/\1XXX:XXX/g' | - # Remove metrics and metas in logged traces (their order is inconsistent) - perl -p -e 's/"(meta|metrics)":{(.*?)}/"\1":{"XXXX": "XXXX"}/g' | - # Normalize enhanced metric datadog_lambda tag - perl -p -e "s/(datadog_lambda:v)[0-9\.]+/\1X.X.X/g" | - # Normalize lookup resource - perl -p -e "s/(\"resource\":\"169.)[0-9\.]+/\1X.X.X/g" | - # Normalize Axios version - perl -p -e "s/User-Agent:axios\/\d+\.\d+\.\d+/User-Agent:axios\/X\.X\.X/g" | - # Remove init start line - perl -p -e "s/INIT_START.*//g" | - sed -E "s/(tracestate\:)([A-Za-z0-9\-\=\:\;].+)/\1XXX/g" | - sed -E "s/(\"_dd.p.tid\"\: \")[a-z0-9\.\-]+/\1XXXX/g" | - sed -E "s/(_dd.p.tid=)[a-z0-9\.\-]+/\1XXXX/g" - ) - - if [ ! -f $function_snapshot_path ]; then + if [ ! -f "$function_snapshot_path" ]; then # If no snapshot file exists yet, we create one echo "Writing logs to $function_snapshot_path because no snapshot exists yet" - echo "$logs" >$function_snapshot_path + printf '%s\n' "$logs" > "$function_snapshot_path" else + if ! normalized_snapshot=$(RUN_ID="${!run_id}" \ + "$scripts_dir/normalize_integration_logs.sh" aws formatted < "$function_snapshot_path"); then + echo "FAILURE: Could not normalize snapshot for $function_name" >&2 + mismatch_found=true + continue + fi # Compare new logs to snapshots - diff_output=$(echo "$logs" | sort | diff -w - <(sort $function_snapshot_path)) + diff_output=$(printf '%s\n' "$logs" | sort | diff -w - <(printf '%s\n' "$normalized_snapshot" | sort)) if [ $? -eq 1 ]; then if [ -n "$UPDATE_SNAPSHOTS" ]; then # If $UPDATE_SNAPSHOTS is set to true write the new logs over the current snapshot echo "Overwriting log snapshot for $function_snapshot_path" - echo "$logs" >$function_snapshot_path + printf '%s\n' "$logs" > "$function_snapshot_path" else echo "Failed: Mismatch found between new $function_name logs (first) and snapshot (second):" echo "$diff_output" diff --git a/scripts/wait_for_complete_logs.sh b/scripts/wait_for_complete_logs.sh new file mode 100644 index 00000000..9f364eff --- /dev/null +++ b/scripts/wait_for_complete_logs.sh @@ -0,0 +1,63 @@ +#!/bin/bash + +function wait_for_complete_logs() { + if [ "$#" -lt 4 ]; then + echo "wait_for_complete_logs requires an expected count, attempts, interval, and command" >&2 + return 2 + fi + + local expected_completion_count=$1 + local max_attempts=$2 + local interval_seconds=$3 + shift 3 + + case "$expected_completion_count" in + ''|*[!0-9]*|0) + echo "Expected completion count must be a positive integer" >&2 + return 2 + ;; + esac + case "$max_attempts" in + ''|*[!0-9]*|0) + echo "Maximum attempts must be a positive integer" >&2 + return 2 + ;; + esac + case "$interval_seconds" in + ''|*[!0-9]*) + echo "Retry interval must be a non-negative integer" >&2 + return 2 + ;; + esac + + local attempt=1 + local command_status=0 + local raw_logs='' + local completion_count=0 + + while [ "$attempt" -le "$max_attempts" ]; do + completion_count=0 + if raw_logs=$("$@"); then + completion_count=$(printf '%s\n' "$raw_logs" | grep -c '^END Duration:' || true) + if [ "$completion_count" -ge "$expected_completion_count" ]; then + printf '%s\n' "$raw_logs" + return 0 + fi + echo "Waiting for complete logs: attempt $attempt/$max_attempts found $completion_count of" \ + "$expected_completion_count completion records" >&2 + else + command_status=$? + echo "Log command attempt $attempt/$max_attempts failed with exit code $command_status" >&2 + fi + + if [ "$attempt" -lt "$max_attempts" ]; then + sleep "$interval_seconds" + fi + attempt=$((attempt + 1)) + done + + echo "FAILURE: Logs remained incomplete after $max_attempts attempts; found $completion_count of" \ + "$expected_completion_count completion records" >&2 + printf '%s\n' "$raw_logs" | tail -30 >&2 + return 1 +} diff --git a/src/integration-log-scripts.spec.ts b/src/integration-log-scripts.spec.ts new file mode 100644 index 00000000..83e96c65 --- /dev/null +++ b/src/integration-log-scripts.spec.ts @@ -0,0 +1,391 @@ +import { spawnSync, SpawnSyncReturns } from "node:child_process"; +import { chmodSync, cpSync, mkdirSync, mkdtempSync, readFileSync, rmSync, writeFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +const repoPath = join(__dirname, ".."); +const normalizerPath = join(repoPath, "scripts", "normalize_integration_logs.sh"); +const readinessPath = join(repoPath, "scripts", "wait_for_complete_logs.sh"); +const runnerPath = join(repoPath, "scripts", "run_integration_tests.sh"); +const waitInvocation = 'source "$1"; shift; wait_for_complete_logs "$@"'; + +const standardLogs = [ + JSON.stringify({ + meta: { + cold_start: "true", + service: "checkout", + }, + metrics: { + stable: 1, + }, + tags: ["cold_start:true"], + }), + "END Duration: 12.34 ms Memory Used: 128 MB", +].join("\n"); + +const proactiveLogs = [ + "INIT_START Runtime Version: nodejs:22.v1", + JSON.stringify({ + meta: { + cold_start: "false", + proactive_initialization: 1, + service: "checkout", + }, + metrics: { + proactive_initialization: 1, + stable: 1, + }, + tags: ["proactive_initialization:true", "cold_start:false"], + }), + "END Duration: 12.34 ms Memory Used: 128 MB (init: 42.1 ms)", +].join("\n"); + +const rieVolatileLogs = [ + 'mock-http saw headers: {"x-datadog-trace-id":"123","x-datadog-parent-id":"456","traceparent":"00-abc-def-01","tracestate":"dd=s:1"}', + "2026-09-02T01:30:00.000Z\trequest-id\tERROR\t(node:123) TimeoutOverflowWarning: 2147483648", + JSON.stringify({ requestId: "12345678-1234-1234-1234-123456789abc", "dns.addresses": "172.18.0.4" }), + "LocalProcessSupervisor.Exec pid=123", + "(Use `node --trace-warnings ...` to show where the warning was created)", +].join("\n"); + +/** + * @param input raw Lambda logs + * @param platform integration-test platform + * @param runId optional deployment run ID + * @param inputFormat raw logs or formatted snapshot input + */ +function normalize( + input: string, + platform: "aws" | "rie", + runId?: string, + inputFormat: "raw" | "formatted" = "raw", +): string { + const result = spawnSync(normalizerPath, [platform, inputFormat], { + encoding: "utf8", + env: { + ...process.env, + RUN_ID: runId ?? "", + }, + input, + }); + + expect(result.status).toBe(0); + return result.stdout; +} + +/** + * @param expectedCompletionCount required Serverless completion records + * @param maxAttempts maximum command attempts + * @param retryIntervalSeconds delay between attempts + * @param command command and arguments that fetch logs + */ +function waitForCompleteLogs( + expectedCompletionCount: number, + maxAttempts: number, + retryIntervalSeconds: number, + command: string[], +): SpawnSyncReturns { + return spawnSync( + "bash", + [ + "-c", + waitInvocation, + "wait-for-complete-logs", + readinessPath, + String(expectedCompletionCount), + String(maxAttempts), + String(retryIntervalSeconds), + ...command, + ], + { encoding: "utf8" }, + ); +} + +describe("integration log normalization", () => { + it("normalizes AWS scheduling differences", () => { + const normalizedProactiveLogs = normalize(proactiveLogs, "aws"); + + expect(normalizedProactiveLogs).not.toContain("INIT_START"); + expect(normalizedProactiveLogs).not.toContain("proactive_initialization"); + expect(normalizedProactiveLogs).not.toContain("cold_start:false"); + expect(normalizedProactiveLogs).toContain('"cold_start": "XXXX"'); + expect(normalizedProactiveLogs).toContain("cold_start:XXXX"); + expect(normalizedProactiveLogs).toBe(normalize(standardLogs, "aws")); + expect(normalize(`\n${standardLogs}`, "aws")).toBe(normalize(standardLogs, "aws")); + }); + + it("preserves deterministic RIE cold-start output", () => { + const normalizedProactiveLogs = normalize(proactiveLogs, "rie"); + + expect(normalizedProactiveLogs).not.toContain("proactive_initialization"); + expect(normalizedProactiveLogs).toContain('"cold_start": "false"'); + expect(normalizedProactiveLogs).toContain("cold_start:false"); + expect(normalizedProactiveLogs).not.toBe(normalize(standardLogs, "rie")); + }); + + it("preserves stable telemetry differences", () => { + const changedLogs = standardLogs.replace("checkout", "payments"); + + expect(normalize(changedLogs, "aws")).not.toBe(normalize(standardLogs, "aws")); + }); + + it("does not reformat formatted snapshots", () => { + const normalizedLogs = normalize(JSON.stringify({ tags: ["runtime:nodejs18.x"] }), "aws"); + + expect(normalize(normalizedLogs, "aws", undefined, "formatted")).toBe(normalizedLogs); + }); + + it("normalizes RIE-specific volatile values", () => { + const normalizedLogs = normalize(rieVolatileLogs, "rie"); + + expect(normalizedLogs).toContain('"x-datadog-trace-id":"XXXX"'); + expect(normalizedLogs).toContain('"x-datadog-parent-id":"XXXX"'); + expect(normalizedLogs).toContain('"traceparent":"XXXX"'); + expect(normalizedLogs).toContain('"tracestate":"XXXX"'); + expect(normalizedLogs).toContain("XXXX-XX-XXTXX:XX:XX.XXXZ"); + expect(normalizedLogs).toContain("(node:XX) TimeoutOverflowWarning: XXXX"); + expect(normalizedLogs).toContain('"requestId": "XXXX"'); + expect(normalizedLogs).toContain('"dns.addresses": "XXXX"'); + expect(normalizedLogs).toContain("LocalProcessSupervisor.Exec pid=XX"); + expect(normalizedLogs).not.toContain("trace-warnings"); + }); + + it("strips a literal run ID", () => { + const runId = "id.with+characters"; + + expect(normalize("function-" + runId, "aws", runId)).toContain("function-XXXX"); + }); + + it("rejects an unsupported platform", () => { + const result = spawnSync(normalizerPath, ["azure"], { + encoding: "utf8", + input: standardLogs, + }); + + expect(result.status).toBe(2); + expect(result.stderr).toContain("Unsupported integration-test platform: azure"); + }); + + it("requires a platform", () => { + const result = spawnSync(normalizerPath, [], { + encoding: "utf8", + input: standardLogs, + }); + + expect(result.status).toBe(2); + expect(result.stderr).toContain("Usage:"); + }); + + it("rejects an unsupported log format", () => { + const result = spawnSync(normalizerPath, ["aws", "compact"], { + encoding: "utf8", + input: standardLogs, + }); + + expect(result.status).toBe(2); + expect(result.stderr).toContain("Unsupported integration-test log format: compact"); + }); +}); + +describe("integration log readiness", () => { + it("keeps successful command diagnostics out of returned logs", () => { + const producer = ["bash", "-c", "printf 'serverless warning\\n' >&2; printf 'END Duration: 1 ms\\n'"]; + const result = waitForCompleteLogs(1, 1, 0, producer); + + expect(result.status).toBe(0); + expect(result.stdout).toBe("END Duration: 1 ms\n"); + expect(result.stderr).toContain("serverless warning"); + }); + + it("retries command failures and incomplete results", () => { + const temporaryDirectory = mkdtempSync(join(tmpdir(), "lambda-log-wait-")); + const attemptPath = join(temporaryDirectory, "attempt"); + const producerScript = [ + "attempt=0", + 'if [ -f "$1" ]; then', + ' read -r attempt < "$1"', + "fi", + "attempt=$((attempt + 1))", + 'printf \'%s\\n\' "$attempt" > "$1"', + 'if [ "$attempt" -eq 1 ]; then', + " printf 'temporary failure\\n' >&2", + " exit 7", + "fi", + "printf 'END Duration: 1 ms\\n'", + 'if [ "$attempt" -ge 3 ]; then', + " printf 'END Duration: 1 ms\\n'", + "fi", + ].join("\n"); + const producer = ["bash", "-c", producerScript, "log-producer", attemptPath]; + + try { + const result = waitForCompleteLogs(2, 3, 0, producer); + + expect(result.status).toBe(0); + expect(result.stdout).toBe("END Duration: 1 ms\nEND Duration: 1 ms\n"); + expect(result.stderr).toContain("attempt 1/3 failed with exit code 7"); + expect(result.stderr).toContain("attempt 2/3 found 1 of 2 completion records"); + } finally { + rmSync(temporaryDirectory, { force: true, recursive: true }); + } + }); + + it("fails after the final command error", () => { + const result = waitForCompleteLogs(1, 2, 0, ["bash", "-c", "printf 'no logs\\n' >&2; exit 4"]); + + expect(result.status).toBe(1); + expect(result.stderr).toContain("attempt 2/2 failed with exit code 4"); + expect(result.stderr).toContain("Logs remained incomplete after 2 attempts"); + }); + + it("fails after the final incomplete result", () => { + const result = waitForCompleteLogs(2, 1, 0, ["printf", "END Duration: 1 ms\n"]); + + expect(result.status).toBe(1); + expect(result.stderr).toContain("found 1 of 2 completion records"); + }); + + it("rejects a zero expected completion count", () => { + const result = waitForCompleteLogs(0, 1, 0, ["true"]); + + expect(result.status).toBe(2); + expect(result.stderr).toContain("Expected completion count must be a positive integer"); + }); + + it("rejects a zero maximum attempt count", () => { + const result = waitForCompleteLogs(1, 0, 0, ["true"]); + + expect(result.status).toBe(2); + expect(result.stderr).toContain("Maximum attempts must be a positive integer"); + }); + + it("rejects a negative retry interval", () => { + const result = waitForCompleteLogs(1, 1, -1, ["true"]); + + expect(result.status).toBe(2); + expect(result.stderr).toContain("Retry interval must be a non-negative integer"); + }); + + it("requires a log command", () => { + const result = waitForCompleteLogs(1, 1, 0, []); + + expect(result.status).toBe(2); + expect(result.stderr).toContain("requires an expected count, attempts, interval, and command"); + }); +}); + +describe("integration test runner", () => { + it("keeps script paths valid after changing directories", () => { + const temporaryDirectory = mkdtempSync(join(tmpdir(), "lambda-integration-runner-")); + const temporaryRepo = join(temporaryDirectory, "repo"); + const temporaryScripts = join(temporaryRepo, "scripts"); + const temporaryIntegrationTests = join(temporaryRepo, "integration_tests"); + const temporaryBin = join(temporaryDirectory, "bin"); + const normalizerArgumentsPath = join(temporaryDirectory, "normalizer-arguments"); + const handlerNames = [ + "async-metrics", + "esm", + "sync-metrics", + "http-requests", + "process-input-traced", + "throw-error-traced", + "status-code-500s", + "container-cjs", + "container-esm", + ]; + + mkdirSync(temporaryScripts, { recursive: true }); + mkdirSync(join(temporaryIntegrationTests, "input_events"), { recursive: true }); + mkdirSync(join(temporaryIntegrationTests, "snapshots", "logs"), { recursive: true }); + mkdirSync(join(temporaryIntegrationTests, "snapshots", "return_values"), { recursive: true }); + mkdirSync(temporaryBin); + cpSync(runnerPath, join(temporaryScripts, "run_integration_tests.sh")); + cpSync(readinessPath, join(temporaryScripts, "wait_for_complete_logs.sh")); + cpSync( + join(repoPath, "integration_tests", "input_events", "api-gateway-get.json"), + join(temporaryIntegrationTests, "input_events", "api-gateway-get.json"), + ); + cpSync(join(repoPath, "integration_tests", "parse-json.js"), join(temporaryIntegrationTests, "parse-json.js")); + mkdirSync(join(temporaryIntegrationTests, "container", "cjs"), { recursive: true }); + mkdirSync(join(temporaryIntegrationTests, "container", "esm"), { recursive: true }); + for (const handlerName of handlerNames) { + cpSync( + join(repoPath, "integration_tests", "snapshots", "logs", `${handlerName}_node18.log`), + join(temporaryIntegrationTests, "snapshots", "logs", `${handlerName}_node18.log`), + ); + cpSync( + join(repoPath, "integration_tests", "snapshots", "return_values", `${handlerName}_node18_api-gateway-get.json`), + join(temporaryIntegrationTests, "snapshots", "return_values", `${handlerName}_node18_api-gateway-get.json`), + ); + } + + const commandStub = ["#!/bin/bash", "exit 0", ""].join("\n"); + const normalizerStub = ["#!/bin/bash", 'printf "%s\\n" "$*" >> "$NORMALIZER_ARGUMENTS"', "cat", ""].join("\n"); + const npmStub = ["#!/bin/bash", "touch datadog-lambda-js-test.tgz", ""].join("\n"); + const xxdStub = ["#!/bin/bash", 'printf "01234567\\n"', ""].join("\n"); + const serverlessStub = [ + "#!/bin/bash", + 'command="$1"', + "shift", + 'if [ "$command" = "deploy" ] || [ "$command" = "remove" ]; then', + " exit 0", + "fi", + 'while [ "$#" -gt 0 ]; do', + ' case "$1" in', + " -f)", + ' function_name="$2"', + " shift 2", + " ;;", + " --path)", + ' input_path="$2"', + " shift 2", + " ;;", + " *)", + " shift", + " ;;", + " esac", + "done", + 'handler_name="${function_name%_node}"', + 'if [ "$command" = "invoke" ]; then', + ' input_name="$(basename "${input_path%.json}")"', + ' cat "./snapshots/return_values/${handler_name}_${RUNTIME}_${input_name}.json"', + "else", + ' cat "./snapshots/logs/${handler_name}_${RUNTIME}.log"', + "fi", + "", + ].join("\n"); + + writeFileSync(join(temporaryScripts, "normalize_integration_logs.sh"), normalizerStub); + writeFileSync(join(temporaryBin, "yarn"), commandStub); + writeFileSync(join(temporaryBin, "npm"), npmStub); + writeFileSync(join(temporaryBin, "serverless"), serverlessStub); + writeFileSync(join(temporaryBin, "xxd"), xxdStub); + chmodSync(join(temporaryBin, "yarn"), 0o755); + chmodSync(join(temporaryBin, "npm"), 0o755); + chmodSync(join(temporaryBin, "serverless"), 0o755); + chmodSync(join(temporaryBin, "xxd"), 0o755); + chmodSync(join(temporaryScripts, "normalize_integration_logs.sh"), 0o755); + + try { + const result = spawnSync("./scripts/run_integration_tests.sh", [], { + cwd: temporaryRepo, + encoding: "utf8", + env: { + ...process.env, + AWS_SECRET_ACCESS_KEY: "test", + DD_API_KEY: "test", + NORMALIZER_ARGUMENTS: normalizerArgumentsPath, + PATH: `${temporaryBin}:${process.env.PATH}`, + RUNTIME_PARAM: "18", + }, + }); + + expect(result.status).toBe(0); + expect(result.stderr).toBe(""); + expect(result.stdout).toContain("SUCCESS: No difference found between snapshots and new return values or logs"); + expect(readFileSync(normalizerArgumentsPath, "utf8")).toContain("aws formatted\n"); + } finally { + rmSync(temporaryDirectory, { force: true, recursive: true }); + } + }); +}); diff --git a/src/metrics/enhanced-metrics.spec.ts b/src/metrics/enhanced-metrics.spec.ts index f8ac9ddc..cbf87214 100644 --- a/src/metrics/enhanced-metrics.spec.ts +++ b/src/metrics/enhanced-metrics.spec.ts @@ -1,5 +1,5 @@ import { Context } from "aws-lambda"; -import { _resetColdStart } from "../utils/cold-start"; +import { _resetColdStart, setSandboxInit } from "../utils/cold-start"; import { getProcessVersion } from "../utils/process-version"; import { getEnhancedMetricTags, getRuntimeTag } from "./enhanced-metrics"; @@ -83,6 +83,22 @@ describe("getEnhancedMetricTags", () => { ]); }); + it("generates tag list for proactive initialization", () => { + setSandboxInit(0, 10_001); + mockedGetProcessVersion.mockReturnValue("v20.19.0"); + expect(getEnhancedMetricTags(mockContext)).toStrictEqual([ + "region:us-east-1", + "account_id:123497598159", + "functionname:my-test-lambda", + "resource:my-test-lambda", + "memorysize:128", + "cold_start:false", + "proactive_initialization:true", + "datadog_lambda:vX.X.X", + "runtime:nodejs20.x", + ]); + }); + it("doesn't add runtime tag if version is unrecognized", () => { mockedGetProcessVersion.mockReturnValue("v6.3.2"); expect(getEnhancedMetricTags(mockContext)).toStrictEqual([ diff --git a/src/trace/listener.spec.ts b/src/trace/listener.spec.ts index 9cede1f8..42572b77 100644 --- a/src/trace/listener.spec.ts +++ b/src/trace/listener.spec.ts @@ -12,6 +12,7 @@ import { DATADOG_TRACE_ID_HEADER, } from "./context/extractor"; import { TracerWrapper } from "./tracer-wrapper"; +import { _resetColdStart, setSandboxInit } from "../utils/cold-start"; const mockProcessAppsecRequest = jest.fn(); const mockProcessAppsecResponse = jest.fn(); @@ -96,6 +97,7 @@ describe("TraceListener", () => { invokedFunctionArn: "arn:aws:lambda:us-east-1:123456789101:function:my-lambda:1", }; beforeEach(() => { + _resetColdStart(); wrapSpy.mockClear(); mockProcessAppsecRequest.mockClear(); mockProcessAppsecResponse.mockClear(); @@ -108,6 +110,7 @@ describe("TraceListener", () => { }); afterEach(() => { + _resetColdStart(); process.env = oldEnv; }); @@ -141,6 +144,20 @@ describe("TraceListener", () => { ); }); + it("tags proactive initialization on the wrapped span", async () => { + setSandboxInit(0, 10_001); + const listener = new TraceListener(defaultConfig); + await listener.onStartInvocation({}, context as any); + const unwrappedFunc = () => {}; + const wrappedFunc = listener.onWrap(unwrappedFunc); + wrappedFunc(); + await listener.onCompleteInvocation(); + + const options = wrapSpy.mock.calls[0][1]; + expect(options.tags?.cold_start).toBe("false"); + expect(options.tags?.proactive_initialization).toBe(true); + }); + it("wraps dd-trace span around invocation, with trace context from event", async () => { const listener = new TraceListener(defaultConfig); mockController.mockTraceSource = TraceSource.Event;