From 464ec90e04ce447a3b4562cb07e7abe10c4fd2ab Mon Sep 17 00:00:00 2001 From: Tomer Weller Date: Sat, 22 Aug 2026 01:33:05 +0000 Subject: [PATCH 1/2] =?UTF-8?q?Regression=20tests=20for=20#3745=20?= =?UTF-8?q?=E2=80=94=20fail=20on=20current=20main?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add 3 harness tests driving a new --emit-new-lines-only seam that pin the live-tail offset invariant broken by the TOCTOU: the reported offset equals the lines actually read/emitted (no reprint on unchanged file, correct incremental advance across appends). All 7 new assertions fail on main because the seam does not yet exist (Unknown arg → exit 1, no NEW_LAST_LINE: marker). Refs #3745 Co-authored-by: Claude Code --- scripts/test-history-publish-harness.sh | 148 +++++++++++++++++++++++- 1 file changed, 147 insertions(+), 1 deletion(-) diff --git a/scripts/test-history-publish-harness.sh b/scripts/test-history-publish-harness.sh index 1e21f7a0..f27ff54b 100755 --- a/scripts/test-history-publish-harness.sh +++ b/scripts/test-history-publish-harness.sh @@ -457,8 +457,151 @@ test_diagnostic_grep_pins_known_signal_names() { fi } +# ============================================================ +# Tests 10-12: the live-tail diagnostic echo advances its line offset by +# exactly the number of lines it actually read (#3745). +# +# Root cause the tests pin: the old inline live-tail block read validator.log +# twice — a `wc -l` line count then a separate `tail -n +N`. If the log grew +# between the two reads, the recorded offset (from the earlier, smaller count) +# lagged what tail emitted, so the next poll re-tailed from the same offset and +# reprinted already-seen diagnostic lines. The fix collapses this to a single +# read whose new offset is derived from exactly the emitted slice, driven +# offline via the --emit-new-lines-only seam. +# +# FAIL on origin/main: --emit-new-lines-only does not exist (the script hits +# the `*) echo "Unknown arg: $1"; exit 1 ;;` branch — exit 1, no NEW_LAST_LINE: +# marker, matching lines never emitted). Same seam-absent precedent as the +# stall-detector tests 7/8. +# ============================================================ + +# Build a 5-line synthetic validator.log with exactly 2 diagnostic-matching +# lines (WATCHDOG and db_write_ctx families). +make_tail_fixture() { + local name="$1" + local data_dir="$TMPDIR_BASE/tail-fixture-$name" + local log="$data_dir/validator.log" + + mkdir -p "$data_dir" + { + echo "closing ledger 1" + echo "WATCHDOG: scp verify falling behind under load" + echo "closing ledger 2" + echo 'db_write_ctx = "peer-record-update" slow write' + echo "closing ledger 3" + } > "$log" + + echo "$log" +} + +# ------------------------------------------------------------ +# Test 10: reported offset equals the number of lines actually read/emitted. +# A fresh 5-line log (2 matching) tailed from offset 0 must emit exactly those +# 2 diagnostic lines and report NEW_LAST_LINE: 5 — the invariant the TOCTOU +# broke (old code advanced by an independent `wc -l` that could differ from +# what tail read). +# ------------------------------------------------------------ +test_live_tail_offset_matches_consumed_lines() { + local log + log=$(make_tail_fixture "offset") + + local out="$TMPDIR_BASE/out-tail-offset.txt" + local exit_code=0 + "$SCRIPT" --emit-new-lines-only "$log" 0 >"$out" 2>&1 || exit_code=$? + + local emitted + emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c .) + if [[ "$emitted" -eq 2 ]] \ + && grep -q 'WATCHDOG' "$out" && grep -q 'db_write_ctx' "$out"; then + tap_ok "live_tail_emits_exactly_the_matching_lines" + else + tap_not_ok "live_tail_emits_exactly_the_matching_lines" \ + "expected 2 diagnostic lines (WATCHDOG + db_write_ctx), got $emitted: $(cat "$out")" + fi + + if grep -q '^NEW_LAST_LINE: 5$' "$out"; then + tap_ok "live_tail_offset_equals_lines_read" + else + tap_not_ok "live_tail_offset_equals_lines_read" \ + "expected NEW_LAST_LINE: 5, got: $(cat "$out")" + fi +} + +# ------------------------------------------------------------ +# Test 11: idempotent no-reprint on an unchanged file — the direct +# anti-duplicate assertion for the reported symptom. After consuming the 5-line +# log (offset 5), re-tailing the unchanged file from offset 5 must emit no +# diagnostic line, report NEW_LAST_LINE: 5, and exit 0. +# ------------------------------------------------------------ +test_live_tail_no_reprint_on_second_call() { + local log + log=$(make_tail_fixture "noreprint") + + local out="$TMPDIR_BASE/out-tail-noreprint.txt" + local exit_code=0 + "$SCRIPT" --emit-new-lines-only "$log" 5 >"$out" 2>&1 || exit_code=$? + + local emitted + emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c .) + if [[ "$emitted" -eq 0 ]]; then + tap_ok "live_tail_no_reprint_of_seen_lines" + else + tap_not_ok "live_tail_no_reprint_of_seen_lines" \ + "expected no diagnostic lines re-emitted, got $emitted: $(cat "$out")" + fi + + if grep -q '^NEW_LAST_LINE: 5$' "$out"; then + tap_ok "live_tail_offset_unchanged_on_no_growth" + else + tap_not_ok "live_tail_offset_unchanged_on_no_growth" \ + "expected NEW_LAST_LINE: 5, got: $(cat "$out")" + fi + + if [[ $exit_code -eq 0 ]]; then + tap_ok "live_tail_no_reprint_exits_zero" + else + tap_not_ok "live_tail_no_reprint_exits_zero" "exit=$exit_code (expected 0)" + fi +} + +# ------------------------------------------------------------ +# Test 12: correct incremental progress across an append. After consuming the +# 5-line log (offset 5), append 3 lines (1 matching); tailing from offset 5 +# must emit exactly the 1 new matching line and report NEW_LAST_LINE: 8. +# ------------------------------------------------------------ +test_live_tail_incremental_append() { + local log + log=$(make_tail_fixture "append") + + { + echo "closing ledger 4" + echo "straggler timeout waiting on peer" + echo "closing ledger 5" + } >> "$log" + + local out="$TMPDIR_BASE/out-tail-append.txt" + local exit_code=0 + "$SCRIPT" --emit-new-lines-only "$log" 5 >"$out" 2>&1 || exit_code=$? + + local emitted + emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c .) + if [[ "$emitted" -eq 1 ]] && grep -q 'straggler timeout' "$out"; then + tap_ok "live_tail_emits_only_new_matching_line" + else + tap_not_ok "live_tail_emits_only_new_matching_line" \ + "expected 1 new diagnostic line (straggler timeout), got $emitted: $(cat "$out")" + fi + + if grep -q '^NEW_LAST_LINE: 8$' "$out"; then + tap_ok "live_tail_offset_advances_across_append" + else + tap_not_ok "live_tail_offset_advances_across_append" \ + "expected NEW_LAST_LINE: 8, got: $(cat "$out")" + fi +} + # --- Run all tests --- -tap_plan 21 +tap_plan 28 test_never_synced_soft_skip test_synced_no_publish_hard_red @@ -469,6 +612,9 @@ test_workflow_wires_soft_flag test_stall_detector_flags_stale_log test_stall_detector_ignores_fresh_log test_diagnostic_grep_pins_known_signal_names +test_live_tail_offset_matches_consumed_lines +test_live_tail_no_reprint_on_second_call +test_live_tail_incremental_append echo "" echo "# Results: $PASS_COUNT/$TEST_COUNT passed, $FAIL_COUNT failed" From 4adb5ef9e89d3d1c4fa75103327e71cef19ed177 Mon Sep 17 00:00:00 2001 From: Tomer Weller Date: Sat, 22 Aug 2026 01:35:22 +0000 Subject: [PATCH 2/2] Fix TOCTOU in test-history-publish.sh live-tail line-count offset The live-tail diagnostic echo read validator.log twice: a `wc -l` line count then a separate `tail -n +N`. If the log grew between the two reads, tail emitted lines beyond the recorded count, but LAST_LOG_LINE was set to the stale smaller count, so the next poll re-tailed from the same offset and reprinted already-seen diagnostic lines. Collapse to a single read: extract emit_new_diagnostic_lines(), which captures the new slice in one `tail`, derives the new absolute offset from exactly that slice (last_line + consumed), and pipes it through the diagnostic grep. With a single read there is no window for concurrent growth to desync the offset from what was printed. Relocate DIAG_GREP_PATTERN to the config region so both the poll loop and the new --emit-new-lines-only offline test seam share it. Refs #3745 Co-authored-by: Claude Code --- scripts/test-history-publish-harness.sh | 6 +- scripts/test-history-publish.sh | 87 +++++++++++++++++++++---- 2 files changed, 76 insertions(+), 17 deletions(-) diff --git a/scripts/test-history-publish-harness.sh b/scripts/test-history-publish-harness.sh index f27ff54b..50d85d1b 100755 --- a/scripts/test-history-publish-harness.sh +++ b/scripts/test-history-publish-harness.sh @@ -510,7 +510,7 @@ test_live_tail_offset_matches_consumed_lines() { "$SCRIPT" --emit-new-lines-only "$log" 0 >"$out" 2>&1 || exit_code=$? local emitted - emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c .) + emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c . || true) if [[ "$emitted" -eq 2 ]] \ && grep -q 'WATCHDOG' "$out" && grep -q 'db_write_ctx' "$out"; then tap_ok "live_tail_emits_exactly_the_matching_lines" @@ -542,7 +542,7 @@ test_live_tail_no_reprint_on_second_call() { "$SCRIPT" --emit-new-lines-only "$log" 5 >"$out" 2>&1 || exit_code=$? local emitted - emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c .) + emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c . || true) if [[ "$emitted" -eq 0 ]]; then tap_ok "live_tail_no_reprint_of_seen_lines" else @@ -584,7 +584,7 @@ test_live_tail_incremental_append() { "$SCRIPT" --emit-new-lines-only "$log" 5 >"$out" 2>&1 || exit_code=$? local emitted - emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c .) + emitted=$(grep -v '^NEW_LAST_LINE:' "$out" | grep -c . || true) if [[ "$emitted" -eq 1 ]] && grep -q 'straggler timeout' "$out"; then tap_ok "live_tail_emits_only_new_matching_line" else diff --git a/scripts/test-history-publish.sh b/scripts/test-history-publish.sh index f92fc6b1..134ec857 100755 --- a/scripts/test-history-publish.sh +++ b/scripts/test-history-publish.sh @@ -13,6 +13,7 @@ # ./scripts/test-history-publish.sh --classify-only /path/to/data-dir # offline classifier (tests) # ./scripts/test-history-publish.sh --stall-threshold 180 # in-loop stall detector threshold # ./scripts/test-history-publish.sh --classify-stall-only /path/to/validator.log 180 # offline stall classifier (tests) +# ./scripts/test-history-publish.sh --emit-new-lines-only /path/to/validator.log 0 # offline live-tail diagnostic emitter (tests) # # Exit codes: # 0 = checkpoint matches SDF archive (or an environmental sync-timeout was @@ -120,6 +121,25 @@ STALL_THRESHOLD_SECS=180 # Used by scripts/test-history-publish-harness.sh. CLASSIFY_STALL_LOG="" CLASSIFY_STALL_THRESHOLD="" +# Offline test seam: when set (via --emit-new-lines-only ) +# run only emit_new_diagnostic_lines() against an existing log file, echo the +# new diagnostic-filtered slice, and print the new absolute offset as +# `NEW_LAST_LINE: ` — no validator/build/testnet required. Used by +# scripts/test-history-publish-harness.sh. +EMIT_NEW_LOG="" +EMIT_NEW_LAST_LINE="" + +# Live diagnostic tail (#3741): grep filter for the known diagnostic families +# already root-caused for this exact fixture (#3727: SCP-verify falling behind +# under load) and the #3702 db_write_ctx/WAL-contention instrumentation. +# Grep-filtered (not a full firehose) so it doesn't meaningfully add to CI log +# volume or runner I/O load. Pinned by +# scripts/test-history-publish-harness.sh::test_diagnostic_grep_pins_known_signal_names +# so a future wording change in the Rust source breaks that test loudly instead +# of silently rotting this filter into a no-op. Defined here (up in the config +# region) so both the --emit-new-lines-only seam and the poll loop share one +# definition. +DIAG_GREP_PATTERN='WATCHDOG|maxtps_scp|database is locked|straggler timeout|db_write_ctx' # The exact run-loop sync marker (crates/app/src/run_cmd.rs::wait_for_sync logs # tracing::info!(..., "Node is synced") once on reaching Synced/Validating). This @@ -142,6 +162,7 @@ while [[ $# -gt 0 ]]; do --classify-only) CLASSIFY_ONLY_DIR="$2"; shift 2 ;; --stall-threshold) STALL_THRESHOLD_SECS="$2"; shift 2 ;; --classify-stall-only) CLASSIFY_STALL_LOG="$2"; CLASSIFY_STALL_THRESHOLD="$3"; shift 3 ;; + --emit-new-lines-only) EMIT_NEW_LOG="$2"; EMIT_NEW_LAST_LINE="$3"; shift 3 ;; -h|--help) sed -n '3,14p' "$0" | sed 's/^# \?//' exit 0 ;; @@ -255,6 +276,54 @@ if [[ -n "$CLASSIFY_STALL_LOG" ]]; then exit 0 fi +# --- Incremental live-tail diagnostic echo (#3741, #3745) --- +# Read the new slice of starting after , echo the lines +# matching to stdout, and report the new absolute line offset via the +# LAST_LOG_LINE_OUT global. Pure except for that stdout + the one global, so the +# harness can drive it offline via --emit-new-lines-only. +# +# The offset is derived from EXACTLY the slice that was read in a SINGLE `tail` +# (not from an independent second `wc -l < file`), which is the fix for the +# #3745 TOCTOU: with only one read there is no window for the log to grow +# between a line-count and the tail, so the recorded offset can never lag what +# was actually emitted and already-seen lines are never reprinted. Anything +# appended after this single read is simply picked up on the next poll. +emit_new_diagnostic_lines() { + local log_file="$1" + local last_line="$2" + local pattern="$3" + + local slice + slice=$(tail -n "+$(( last_line + 1 ))" "$log_file" 2>/dev/null || true) + + if [[ -z "$slice" ]]; then + # No new content (or unreadable log) — no advance, nothing printed. Mirrors + # the old `CURRENT_LOG_LINES > LAST_LOG_LINE` guard's no-op branch. + LAST_LOG_LINE_OUT="$last_line" + return 0 + fi + + # `consumed` counts the lines in the captured slice. Note bash `$(...)` strips + # trailing newlines, so trailing blank line(s) are under-counted and may be + # re-read next poll — harmless, since blank lines never match the filter, so + # no visible duplicate. + local consumed + consumed=$(printf '%s\n' "$slice" | wc -l) + LAST_LOG_LINE_OUT=$(( last_line + consumed )) + + printf '%s\n' "$slice" | grep -E "$pattern" || true +} + +# Offline test seam: emit the new diagnostic-filtered slice of a single log +# starting after , print the new absolute offset, and exit 0. +# --emit-new-lines-only +if [[ -n "$EMIT_NEW_LOG" ]]; then + LAST_LOG_LINE_OUT=0 + emit_new_diagnostic_lines "$EMIT_NEW_LOG" "$EMIT_NEW_LAST_LINE" "$DIAG_GREP_PATTERN" + echo "NEW_LAST_LINE: $LAST_LOG_LINE_OUT" + exit 0 +fi + # --- Data dirs --- if [[ -n "$DATA_DIR_OVERRIDE" ]]; then DATA_DIR="$DATA_DIR_OVERRIDE" @@ -379,15 +448,8 @@ echo HAS_FILE="$HISTORY_DIR/.well-known/stellar-history.json" echo "Waiting for first published checkpoint (timeout: ${TIMEOUT}s, stall threshold: ${STALL_THRESHOLD_SECS}s)..." -# Live diagnostic tail (#3741): grep filter for the known diagnostic families -# already root-caused for this exact fixture (#3727: SCP-verify falling behind -# under load) and the #3702 db_write_ctx/WAL-contention instrumentation. -# Grep-filtered (not a full firehose) so it doesn't meaningfully add to CI log -# volume or runner I/O load. Pinned by -# scripts/test-history-publish-harness.sh::test_diagnostic_grep_pins_known_signal_names -# so a future wording change in the Rust source breaks that test loudly instead -# of silently rotting this filter into a no-op. -DIAG_GREP_PATTERN='WATCHDOG|maxtps_scp|database is locked|straggler timeout|db_write_ctx' +# DIAG_GREP_PATTERN is defined up in the config region so both the poll loop +# below and the --emit-new-lines-only test seam share one definition. LAST_LOG_LINE=0 START_TIME=$(date +%s) @@ -438,11 +500,8 @@ while true; do # captures even under an external job-level cancellation (unlike the # artifact upload). No background process/PID cleanup needed — this stays # inside the existing single-threaded 5s poll loop. - CURRENT_LOG_LINES=$(wc -l < "$LOG_FILE" 2>/dev/null || echo 0) - if [[ "$CURRENT_LOG_LINES" -gt "$LAST_LOG_LINE" ]]; then - tail -n "+$(( LAST_LOG_LINE + 1 ))" "$LOG_FILE" | grep -E "$DIAG_GREP_PATTERN" || true - LAST_LOG_LINE="$CURRENT_LOG_LINES" - fi + emit_new_diagnostic_lines "$LOG_FILE" "$LAST_LOG_LINE" "$DIAG_GREP_PATTERN" + LAST_LOG_LINE="$LAST_LOG_LINE_OUT" # Check for published HAS if [[ -f "$HAS_FILE" ]]; then