testing/mesh-lab: nat-lan cpu-pinning sidecar + trace overlay + stall_signature

Three deltas to the mesh-lab nat-lan suite for stall characterization:

- FIPS_NAT_LAN_CPUSET env-var-driven CPU-pinning sidecar in
  run_nat_lan, mirroring the bloom-storm pattern. Pinning is needed
  because the mesh-lab compose-resource-limits.yml override is
  rekey-family service-name specific (rekey-* / rekey-accept-off-* /
  rekey-outbound-only-*), so it does not constrain the nat-lan
  containers. Default cpuset 0,1 mimics a GHA 2-core runner; empty
  disables the sidecar.

- New compose-trace-nat.yml overlay that bumps RUST_LOG to trace on
  discovery::nostr, transport::udp, node::lifecycle,
  handlers::handshake, handlers::forwarding — the modules covering
  the cross-init / adoption / handshake path. Picked up by the
  nat-test.sh COMPOSE array via a new FIPS_NAT_EXTRA_COMPOSE
  colon-separated env-var hook. run_nat_lan sets this hook when
  FIPS_MESH_LAB_TRACE is non-empty; the README env-var section
  updated to reflect that FIPS_MESH_LAB_TRACE now applies to nat-lan
  in addition to the rekey-family.

- parse_nat_lan extended with a per-node stall_signature emitting
  last-occurrence timestamps for eight event categories (startup,
  discovery, adoption, handshake_init, msg2_sent, cross_init_ignore_*,
  handshake_failed) plus derived last_meaningful_event_ts,
  last_event_category, silent_gap_s. Top-level stall_class binned as
  no_timeout / silent / localized / distributed / incomplete from
  the per-node categories. Aggregation phase consumes the per-rep
  signatures across a characterization run to classify stall
  mechanism.

Wired support in nat-test.sh: FIPS_NAT_EXTRA_COMPOSE colon-separated
list of repo-relative or absolute compose files layered onto the
base via the COMPOSE array; FIPS_NAT_SKIP_FINAL_CLEANUP gates the
success-path teardown so the mesh-lab harness can capture docker
logs before tearing down (failure paths already returned without
cleanup, leaving stall-state containers intact for capture).

Smoke-tested on idle profile with TRACE on: 1 rep PASS, 32/36 TRACE
lines per node, signature.json events all populated with the
expected category timestamps.

testing/mesh-lab/README.md

@@ -96,16 +96,24 @@ each rep does, set them in the invoking shell:
   injection point.
 
 - **`FIPS_MESH_LAB_TRACE`** — when set to any non-empty value, the
-  harness layers `compose-trace.yml` on top of the base + resource-
-  limits compose stack. That override bumps `RUST_LOG` to trace
-  level on the modules relevant to the rekey-class flake: `rekey`,
-  `handshake`, `forwarding`, `session`, `encrypted`, `mmp`. Use
-  only when capturing primary failure-moment evidence for mechanism
-  investigation — log volume increases substantially. Without this
-  knob, daemon logs only capture state transitions (rekey cutover,
-  K-bit flip), not per-datagram forwarding decisions, which makes
-  evidence collection for routing-state stalls effectively
-  impossible.
+  harness layers a suite-specific trace-RUST_LOG compose override
+  on top of the base stack. Module sets are per-suite:
+  - rekey / rekey-accept-off / rekey-outbound-only — `rekey`,
+    `handshake`, `forwarding`, `session`, `encrypted`, `mmp`
+    (via `compose-trace.yml`).
+  - nat-lan — `discovery::nostr`, `transport::udp`,
+    `node::lifecycle`, `handlers::handshake`, `handlers::forwarding`
+    (via `compose-trace-nat.yml`, picked up by
+    `testing/nat/scripts/nat-test.sh` through the
+    `FIPS_NAT_EXTRA_COMPOSE` env-var hook).
+  - bloom-storm — no compose override applies; chaos uses its own
+    python sim runner.
+
+  Use only when capturing primary failure-moment evidence for
+  mechanism investigation — log volume increases substantially.
+  Without this knob, daemon logs only capture state transitions and
+  not per-datagram forwarding decisions, which makes evidence
+  collection for routing-state stalls effectively impossible.
 
 - **`FIPS_BLOOM_STORM_CPUSET`** — comma-separated CPU set for the
   bloom-storm dispatch's container-pinning sidecar (default
@@ -116,6 +124,17 @@ each rep does, set them in the invoking shell:
   relax, or to the empty string to disable the sidecar entirely.
   Only applies to the `bloom-storm` suite; other suites ignore it.
 
+- **`FIPS_NAT_LAN_CPUSET`** — comma-separated CPU set for the
+  nat-lan dispatch's container-pinning sidecar (default `0,1`).
+  Same shape as `FIPS_BLOOM_STORM_CPUSET`, but the sidecar polls
+  for `fips-nat-lan-*` containers and applies the cpuset as the
+  compose-up creates them. The mesh-lab
+  `compose-resource-limits.yml` overlay is rekey-family
+  service-name-specific (services `rekey-*` / `rekey-accept-off-*`
+  / `rekey-outbound-only-*`), so it does NOT constrain the nat-lan
+  containers; the sidecar fills that gap. Only applies to the
+  `nat-lan` suite; other suites ignore it.
+
 - **`FIPS_MESH_LAB_RUNS_DIR`** — root directory for harness output
   (the `runs/<timestamp>/` tree). When unset, the harness falls back
   to an in-tree path under `testing/mesh-lab/` and prints a warning

testing/mesh-lab/compose-trace-nat.yml

@@ -0,0 +1,42 @@
+# Compose override that bumps RUST_LOG to trace level on the modules
+# relevant to NAT-traversal handshake-completion flake evidence
+# collection (ISSUE-2026-0027):
+#
+#   - fips::discovery::nostr            — overlay advert publish/consume
+#                                          (where the cross-init race begins)
+#   - fips::transport::udp              — UDP socket bind/send/recv
+#                                          (where the punch packets flow)
+#   - fips::node::lifecycle             — daemon bootstrap, peer state
+#                                          machine, adoption transitions
+#   - fips::node::handlers::handshake   — Noise handshake msg1/2/3,
+#                                          cross-init tie-breaker
+#                                          ("Ignoring established NAT
+#                                          traversal..." emits here)
+#   - fips::node::handlers::forwarding  — transit/local datagram routing
+#                                          (catches drops post-adoption)
+#
+# Other modules stay at info to keep log volume manageable. The base
+# docker-compose.yml's `*fips-common` env block sets RUST_LOG as a
+# list-form env var (`- RUST_LOG=...`); the override below replaces
+# it entirely via the YAML map form, which is the docker-compose
+# override semantics for the environment field.
+#
+# Service-name layout: only the two `lan-*` services are FIPS daemons;
+# the relay and stun services are not (and don't honor RUST_LOG).
+#
+# Include this override via the FIPS_NAT_EXTRA_COMPOSE env var that
+# testing/nat/scripts/nat-test.sh consults:
+#   FIPS_NAT_EXTRA_COMPOSE=testing/mesh-lab/compose-trace-nat.yml \
+#       bash testing/nat/scripts/nat-test.sh lan
+#
+# The mesh-lab harness sets it automatically when FIPS_MESH_LAB_TRACE
+# is set and the suite is nat-lan.
+
+x-trace-rust-log: &trace-rust-log
+  RUST_LOG: "info,fips::discovery::nostr=trace,fips::transport::udp=trace,fips::node::lifecycle=trace,fips::node::handlers::handshake=trace,fips::node::handlers::forwarding=trace"
+
+services:
+  lan-a:
+    environment: *trace-rust-log
+  lan-b:
+    environment: *trace-rust-log

testing/mesh-lab/run-loop.sh

@@ -327,9 +327,58 @@ mechanism_match_rekey() {
 run_nat_lan() {
     local REP_DIR="$1"
     local rc=0
+
+    # Optional CPU-pinning sidecar. Mirrors the bloom-storm pattern at
+    # run_bloom_storm above. nat-test.sh uses docker-compose, but the
+    # mesh-lab compose-resource-limits.yml override is rekey-family
+    # service-name specific (services rekey-* / rekey-accept-off-* /
+    # rekey-outbound-only-*), so it does NOT constrain the nat-lan
+    # containers (lan-a, lan-b). To pressure-match the GHA 2-core
+    # constraint without adding nat-specific resource-limits files, the
+    # sidecar polls for `fips-nat-lan-*` containers as compose spawns
+    # them and applies `docker update --cpuset-cpus <set>` to each.
+    # Pinning is idempotent — re-applying the same cpuset is a no-op.
+    # Default `0,1` mimics a GHA 2-core runner; set FIPS_NAT_LAN_CPUSET
+    # to a wider set (e.g. `0,1,2,3`) to relax, or to the empty string
+    # to disable the sidecar.
+    local cpuset="${FIPS_NAT_LAN_CPUSET-0,1}"
+    local pinning_pid=""
+    if [ -n "$cpuset" ]; then
+        (
+            while true; do
+                for c in $(docker ps --filter "name=fips-nat-lan-" --format '{{.Names}}' 2>/dev/null); do
+                    docker update --cpuset-cpus "$cpuset" "$c" >/dev/null 2>&1 || true
+                done
+                sleep 0.5
+            done
+        ) &
+        pinning_pid=$!
+        echo "nat-lan: cpu-pinning sidecar PID $pinning_pid (cpuset=$cpuset)" \
+            >"$REP_DIR/setup.log"
+    fi
+
+    # Trace-logging override. When FIPS_MESH_LAB_TRACE is set, point
+    # nat-test.sh at the nat-specific trace overlay via the
+    # FIPS_NAT_EXTRA_COMPOSE env-var hook in nat-test.sh. The overlay
+    # bumps RUST_LOG to trace on discovery::nostr, transport::udp,
+    # node::lifecycle, handlers::handshake, handlers::forwarding —
+    # the modules covering the cross-init / adoption / handshake
+    # path that ISSUE-2026-0027 exhibits. Path is repo-relative.
+    local -a env_args=(FIPS_NAT_SKIP_FINAL_CLEANUP=1)
+    if [ -n "${FIPS_MESH_LAB_TRACE:-}" ]; then
+        env_args+=(FIPS_NAT_EXTRA_COMPOSE=testing/mesh-lab/compose-trace-nat.yml)
+        echo "nat-lan: FIPS_MESH_LAB_TRACE set, layering compose-trace-nat.yml" \
+            >>"$REP_DIR/setup.log"
+    fi
+
+    # nat-test.sh's run_lan() tears containers down on the success
+    # path (line 404 cleanup), which races with our docker-logs
+    # capture below. FIPS_NAT_SKIP_FINAL_CLEANUP=1 disables that
+    # final teardown; failure paths in run_lan already leave
+    # containers up. We do the teardown explicitly after capture.
     (
         cd "$REPO_ROOT" || exit 1
-        bash testing/nat/scripts/nat-test.sh lan
+        env "${env_args[@]}" bash testing/nat/scripts/nat-test.sh lan
     ) >"$REP_DIR/test-output.log" 2>&1 || rc=$?
 
     mkdir -p "$REP_DIR/docker-logs"
@@ -337,9 +386,133 @@ run_nat_lan() {
         docker logs "$c" >"$REP_DIR/docker-logs/$c.log" 2>&1 || true
     done
 
+    # Post-capture teardown. nat-test.sh skipped its final cleanup
+    # (skipping is success-path only; failure paths return without
+    # cleanup either way), so we tear down here. Mirrors nat-test.sh's
+    # cleanup() shape: all three profiles + -v --remove-orphans.
+    (
+        cd "$REPO_ROOT" || exit 1
+        docker compose -f testing/nat/docker-compose.yml \
+            --profile cone --profile symmetric --profile lan \
+            down -v --remove-orphans \
+            >>"$REP_DIR/teardown.log" 2>&1 || true
+    )
+
+    if [ -n "$pinning_pid" ]; then
+        kill "$pinning_pid" 2>/dev/null || true
+        wait "$pinning_pid" 2>/dev/null || true
+    fi
+
     return "$rc"
 }
 
+# Extract the timestamp of the last line in $log matching $pattern. The
+# daemon's tracing-subscriber emits ISO 8601 UTC timestamps with sub-
+# second precision as the first token on each line (after ANSI escapes
+# are stripped). Returns the empty string if no line matches. Helper
+# scoped to parse_nat_lan; relies on grep -E semantics.
+_nat_lan_extract_last_ts() {
+    local log="$1"
+    local pattern="$2"
+    [ -f "$log" ] || { echo ""; return; }
+    grep -E "$pattern" "$log" 2>/dev/null \
+        | sed -E 's/\x1b\[[0-9;]*[mK]//g' \
+        | grep -oE '^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9:.]+Z' \
+        | tail -1
+}
+
+# Compute the per-node stall_signature events dict + derived fields by
+# scanning the container's docker log for known event patterns. Echoes
+# a JSON object suitable for inlining into the rep's signature.json.
+_nat_lan_node_stall_signature() {
+    local nodelog="$1"
+
+    local startup_ts nostr_ts adoption_ts handshake_init_ts msg2_sent_ts
+    local cross_init_progress_ts cross_init_connected_ts handshake_failed_ts
+    local last_log_ts
+
+    startup_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Node started')
+    nostr_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Started Nostr UDP NAT traversal attempt|nostr notify loop entered')
+    adoption_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Adopted NAT traversal socket')
+    handshake_init_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Connection initiated')
+    msg2_sent_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Sent msg2 response')
+    cross_init_progress_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Ignoring established NAT traversal while peer handshake is already in progress')
+    cross_init_connected_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Ignoring established NAT traversal for already-connected peer')
+    handshake_failed_ts=$(_nat_lan_extract_last_ts "$nodelog" 'Handshake completion failed')
+    last_log_ts=$(_nat_lan_extract_last_ts "$nodelog" '.')
+
+    # Derive last_meaningful_event_category and ts by string-max across
+    # categories (ISO 8601 string compare == time compare). Empty
+    # category timestamps don't contribute.
+    local cat="" cat_ts=""
+    local -a pairs=(
+        "startup:$startup_ts"
+        "discovery:$nostr_ts"
+        "adoption:$adoption_ts"
+        "handshake_init:$handshake_init_ts"
+        "msg2_sent:$msg2_sent_ts"
+        "cross_init_ignore_progress:$cross_init_progress_ts"
+        "cross_init_ignore_connected:$cross_init_connected_ts"
+        "handshake_failed:$handshake_failed_ts"
+    )
+    local p name ts
+    for p in "${pairs[@]}"; do
+        name="${p%%:*}"
+        ts="${p#*:}"
+        if [ -n "$ts" ] && [[ "$ts" > "$cat_ts" ]]; then
+            cat_ts="$ts"
+            cat="$name"
+        fi
+    done
+
+    # silent_gap_s: seconds between last_meaningful_event_ts and
+    # last_log_ts. Large gap → daemon stayed alive but stopped doing
+    # meaningful work. Computed via Python (date math is fragile in
+    # pure bash). Empty if either timestamp is missing.
+    local silent_gap_s=""
+    if [ -n "$last_log_ts" ] && [ -n "$cat_ts" ]; then
+        silent_gap_s=$(python3 -c "
+from datetime import datetime
+def p(s):
+    return datetime.strptime(s.rstrip('Z')[:26], '%Y-%m-%dT%H:%M:%S.%f' if '.' in s else '%Y-%m-%dT%H:%M:%S')
+try:
+    print(round((p('$last_log_ts') - p('$cat_ts')).total_seconds(), 3))
+except Exception:
+    print('')
+" 2>/dev/null || echo "")
+    fi
+
+    jq -n \
+        --arg last_log "$last_log_ts" \
+        --arg last_meaningful "$cat_ts" \
+        --arg last_cat "$cat" \
+        --arg silent_gap "$silent_gap_s" \
+        --arg startup "$startup_ts" \
+        --arg discovery "$nostr_ts" \
+        --arg adoption "$adoption_ts" \
+        --arg handshake_init "$handshake_init_ts" \
+        --arg msg2_sent "$msg2_sent_ts" \
+        --arg ci_progress "$cross_init_progress_ts" \
+        --arg ci_connected "$cross_init_connected_ts" \
+        --arg hs_failed "$handshake_failed_ts" \
+        '{
+            last_log_ts: (if $last_log == "" then null else $last_log end),
+            last_meaningful_event_ts: (if $last_meaningful == "" then null else $last_meaningful end),
+            last_event_category: (if $last_cat == "" then null else $last_cat end),
+            silent_gap_s: (if $silent_gap == "" then null else ($silent_gap | tonumber) end),
+            events: {
+                startup: (if $startup == "" then null else $startup end),
+                discovery: (if $discovery == "" then null else $discovery end),
+                adoption: (if $adoption == "" then null else $adoption end),
+                handshake_init: (if $handshake_init == "" then null else $handshake_init end),
+                msg2_sent: (if $msg2_sent == "" then null else $msg2_sent end),
+                cross_init_ignore_progress: (if $ci_progress == "" then null else $ci_progress end),
+                cross_init_ignore_connected: (if $ci_connected == "" then null else $ci_connected end),
+                handshake_failed: (if $hs_failed == "" then null else $hs_failed end)
+            }
+        }'
+}
+
 parse_nat_lan() {
     local REP_DIR="$1"
     local log="$REP_DIR/test-output.log"
@@ -355,12 +528,59 @@ parse_nat_lan() {
         cross_init_observed="true"
     fi
 
-    cat <<EOF >"$REP_DIR/signature.json"
-{
-  "peer_adoption_timeout": $peer_adoption_timeout,
-  "cross_init_observed": $cross_init_observed
-}
-EOF
+    # Per-node stall_signature: scan each container's docker log for
+    # known event patterns and extract last-occurrence timestamps. Used
+    # by the aggregation phase to bin stalls into localized (both nodes
+    # last at same category) / distributed (different categories) /
+    # silent (daemon emitted nothing meaningful for >threshold s before
+    # timeout) classes. See _nat_lan_node_stall_signature for the event
+    # taxonomy.
+    local sig_a sig_b
+    sig_a=$(_nat_lan_node_stall_signature "$REP_DIR/docker-logs/fips-nat-lan-a.log")
+    sig_b=$(_nat_lan_node_stall_signature "$REP_DIR/docker-logs/fips-nat-lan-b.log")
+
+    # Top-level stall_class derived from per-node last_event_category:
+    #   no_timeout — peer_adoption_timeout=false (success case)
+    #   silent     — either node's silent_gap_s > 5
+    #   localized  — both nodes' last_event_category is the same
+    #   distributed — categories differ
+    #   incomplete  — categories missing on one or both nodes
+    local stall_class="no_timeout"
+    if [ "$peer_adoption_timeout" = "true" ]; then
+        local cat_a cat_b gap_a gap_b
+        cat_a=$(echo "$sig_a" | jq -r '.last_event_category // ""')
+        cat_b=$(echo "$sig_b" | jq -r '.last_event_category // ""')
+        gap_a=$(echo "$sig_a" | jq -r '.silent_gap_s // 0')
+        gap_b=$(echo "$sig_b" | jq -r '.silent_gap_s // 0')
+        local silent_a silent_b
+        silent_a=$(awk -v g="$gap_a" 'BEGIN{ print (g > 5) ? "1" : "0" }')
+        silent_b=$(awk -v g="$gap_b" 'BEGIN{ print (g > 5) ? "1" : "0" }')
+        if [ "$silent_a" = "1" ] || [ "$silent_b" = "1" ]; then
+            stall_class="silent"
+        elif [ -z "$cat_a" ] || [ -z "$cat_b" ]; then
+            stall_class="incomplete"
+        elif [ "$cat_a" = "$cat_b" ]; then
+            stall_class="localized"
+        else
+            stall_class="distributed"
+        fi
+    fi
+
+    jq -n \
+        --argjson peer_adoption_timeout "$peer_adoption_timeout" \
+        --argjson cross_init_observed "$cross_init_observed" \
+        --argjson sig_a "$sig_a" \
+        --argjson sig_b "$sig_b" \
+        --arg stall_class "$stall_class" \
+        '{
+            peer_adoption_timeout: $peer_adoption_timeout,
+            cross_init_observed: $cross_init_observed,
+            stall_class: $stall_class,
+            stall_signature: {
+                "fips-nat-lan-a": $sig_a,
+                "fips-nat-lan-b": $sig_b
+            }
+        }' >"$REP_DIR/signature.json"
 }
 
 mechanism_match_nat_lan() {

testing/nat/scripts/nat-test.sh

@@ -13,6 +13,21 @@ WAIT_LIB="$ROOT_DIR/testing/lib/wait-converge.sh"
 SCENARIO="${1:-all}"
 COMPOSE=(docker compose -f "$NAT_DIR/docker-compose.yml")
 
+# Optional extra compose-file overlay chain (colon-separated paths), e.g.
+# trace-RUST_LOG overrides supplied by the mesh-lab harness when
+# FIPS_MESH_LAB_TRACE=1. Paths are interpreted relative to the repo root
+# (ROOT_DIR) unless absolute. The mesh-lab harness sets this env var to
+# `testing/mesh-lab/compose-trace-nat.yml` for nat-lan trace runs.
+if [ -n "${FIPS_NAT_EXTRA_COMPOSE:-}" ]; then
+    IFS=':' read -ra _NAT_EXTRA <<< "${FIPS_NAT_EXTRA_COMPOSE}"
+    for _f in "${_NAT_EXTRA[@]}"; do
+        case "$_f" in
+            /*) COMPOSE+=(-f "$_f") ;;
+            *)  COMPOSE+=(-f "$ROOT_DIR/$_f") ;;
+        esac
+    done
+fi
+
 source "$WAIT_LIB"
 
 cleanup() {
@@ -386,7 +401,14 @@ run_lan() {
     source "$NAT_DIR/generated-configs/lan/npubs.env"
     ping_peer fips-nat-lan-a "$NPUB_B"
     ping_peer fips-nat-lan-b "$NPUB_A"
-    cleanup
+    # Skip the final teardown when the mesh-lab harness wraps this
+    # script: it needs to docker-logs the containers before teardown,
+    # and will run its own cleanup after capture. Failure paths above
+    # already leave containers up via the bare `return 1` so the
+    # harness can capture stall-state evidence.
+    if [ -z "${FIPS_NAT_SKIP_FINAL_CLEANUP:-}" ]; then
+        cleanup
+    fi
 }
 
 main() {