Fix TOCTOU in test-history-publish.sh live-tail line-count offset

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 <log_file> <last_line> 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 . || 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"
+    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 . || true)
+    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 . || true)
+    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"

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 <log_file> <last_line>)
+# 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: <n>` — 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 <log_file> starting after <last_line>, echo the lines
+# matching <pattern> 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 <last_line>, print the new absolute offset, and exit 0.
+# --emit-new-lines-only <log_file> <last_line>
+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