diff --git a/scripts/test-history-publish-harness.sh b/scripts/test-history-publish-harness.sh index 1e21f7a0..50d85d1b 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 . || 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" 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