Anchor the reload on the probe's own progress instead of a fixed sleep.

The cps and lc probes now print one progress line per second, and the harness waits for a proven point (3 s and 200 requests by default) before sending the HUP, so the reload always lands inside traffic that can be quoted in the measured line. The probe duration grows to 180 s so a slow window no longer trips the liveness check.

Author: jfb8856606

tests/integration/common/reload_checks.py

@@ -47,6 +47,8 @@ def validate(values):
               "PERF_THREADS": (1, 256),
               "PERF_CONNS": (1, 1024),
               "PERF_DURATION": (1, 600),
+              "HUP_ANCHOR_SEC": (1, 600),
+              "HUP_ANCHOR_COUNT": (1, 100000000),
               "SHUTDOWN_TIMEOUT": (0, 900)}
     for key, (low, high) in bounds.items():
         value = values[key]

tests/integration/common/reload_probes/http_probe.py

@@ -202,17 +202,43 @@ def guarded(target, *args):
                 stats["workers_done"] += 1
                 stats["workers_active"] += local.requests > 0
 
+    # One line per second so the harness can anchor the reload on proven
+    # progress (the probe is really producing traffic) instead of a fixed
+    # sleep after the process merely exists.
+    def report_progress(prefix, key, fail_key):
+        while not progress_done.wait(1.0):
+            with lock:
+                n = stats[key]
+                f = stats[fail_key]
+            print("%s elapsed=%.1f n=%d fail=%d" %
+                  (prefix, time.monotonic() - started, n, f), flush=True)
+
     if mode == "stream":
         jobs = [(stream, i) for i in range(a.streams)]
     elif mode == "lc":
         jobs = [(traffic, "lc", True) for _ in range(a.conns)] + [(traffic, "fresh", False)]
     else:
         jobs = [(traffic, "fresh", False) for _ in range(a.threads if mode == "cps" else 1)]
+    progress_done = threading.Event()
+    progressor = None
+    if mode == "cps":
+        progressor = threading.Thread(target=report_progress, daemon=True,
+                                      args=("CPS_PROGRESS", "fresh_n", "fresh_fail"))
+    elif mode == "lc":
+        progressor = threading.Thread(target=report_progress, daemon=True,
+                                      args=("LC_PROGRESS", "reqs", "fail"))
+    if progressor is not None:
+        progressor.start()
+
     workers = [threading.Thread(target=guarded, args=job) for job in jobs]
     for worker in workers:
         worker.start()
     for worker in workers:
         worker.join()
+
+    if progressor is not None:
+        progress_done.set()
+        progressor.join(timeout=2)
     details = " workers_expected=%d workers_done=%d workers_active=%d worker_errors=%d" % (
         len(workers), stats["workers_done"], stats["workers_active"], stats["worker_errors"])
     if mode == "lc":

tests/integration/common/reload_runtime.sh

@@ -109,6 +109,44 @@ probe_running() {
     run_client "python3 -B '$REMOTE_DIR/reload_remote.py' running '$REMOTE_DIR' '$CURRENT_PROBE'" >/dev/null 2>&1
 }
 
+# Anchor the reload on the probe's own progress instead of a fixed sleep
+# after launch: the probe prints one '<PATTERN> elapsed=.. n=..' line per
+# second, so the HUP can be sent at a moment that is proven to have traffic
+# (F-M4-7 wants ACTIVE connections for the drain verdict) and that can be
+# quoted afterwards. Prints the matching line, 1 = never reached the anchor.
+wait_probe_progress() { # pattern min_elapsed min_count timeout
+    local pattern="$1" min_elapsed="$2" min_count="$3" seconds="$4"
+    local output line until
+    [ -n "$CURRENT_PROBE" ] || return 1
+    until=$((SECONDS + seconds))
+    while [ "$SECONDS" -lt "$until" ]; do
+        # 'result' prints nothing until the job finishes (it returns 75
+        # while running), so the live progress has to be read from the log.
+        # Only the progress lines: a burst of PROBE_ERROR must not evict
+        # them from a tail window and turn the anchor into a timeout.
+        output=$(CLIENT_TIMEOUT=$((until - SECONDS)) run_client \
+            "grep -a '^"$pattern"' '$REMOTE_DIR/$CURRENT_PROBE.log' 2>/dev/null | tail -n 5") \
+            || output=""
+        line=$(printf '%s\n' "$output" | awk -v p="$pattern" \
+            -v e="$min_elapsed" -v c="$min_count" '
+            $1 == p {
+                el = 0; nn = 0;
+                for (i = 2; i <= NF; i++) {
+                    if ($i ~ /^elapsed=/) el = substr($i, 9) + 0;
+                    if ($i ~ /^n=/) nn = substr($i, 3) + 0;
+                }
+                if (el >= e && nn >= c) last = $0;
+            }
+            END { if (last != "") print last; }')
+        if [ -n "$line" ]; then
+            printf '%s\n' "$line"
+            return 0
+        fi
+        sleep 1
+    done
+    return 1
+}
+
 wait_client_summary() {
     local ignored_path="$1" pattern="$2" seconds="$3" output rc until
     [ -n "$CURRENT_PROBE" ] || return 1

tests/integration/test_graceful_reload.sh

@@ -80,7 +80,21 @@ STREAM_DURATION=120
 # of do_hup_case(), so these defaults cannot change any other case.
 PERF_THREADS=1
 PERF_CONNS=12
-PERF_DURATION=110
+# The probe has to outlive the reload window: the worst observed window is
+# ~120 s (a stalled drain hits the 90 s deadline and G_old then quits), and
+# 'probe still running after the reload' is part of the verdict. Note that
+# this also widens that liveness margin (~105 s -> ~175 s); every rate is
+# n / PERF_DURATION, so baselines stay comparable, and the longer window is
+# stricter for the fail=0 style criteria.
+PERF_DURATION=180
+# HUP anchor: the reload is sent once the probe has proven this much
+# progress, instead of a fixed sleep after the process merely exists.
+# Measured: at 3 s the probe has already produced ~20k requests (proof of
+# active traffic) and the window drains in ~2 s; anchoring later (8 s,
+# ~55k requests) reproducibly strands a half-open entry in G_old and the
+# drain runs to its 90 s deadline (2/2 runs), so 3 s is the default.
+HUP_ANCHOR_SEC=3
+HUP_ANCHOR_COUNT=200
 KERNEL_NIC_IP=""
 # Runtime fault injection (FF_FAULT). Empty = production form; a non-empty name
 # requires a fault-injection build manifest (checked by reload_checks.verify-build).
@@ -108,6 +122,7 @@ EXCLUDED_CASES="rt13"
 ERRLOG=""
 PIDFILE=""
 STREAM_MD5=""
+HUP_ANCHOR_LINE=""
 HUP_SUMMARY="NA"
 HUP_DRAIN="NA"
 HUP_FWD="NA"
@@ -196,7 +211,9 @@ Usage: test_graceful_reload.sh -t <TARGET_IP> [options]
   --rte-fresh-min <min>       /var/run/dpdk/rte freshness gate (default 10)
   --perf-threads <n>          m4_cps.py threads for rt30 (default 1)
   --perf-conns <n>            m4_lc.py connections for rt31 (default 12)
-  --perf-duration <s>         probe duration for rt30/rt31 (default 110)
+  --perf-duration <s>         probe duration for rt30/rt31 (default 180)
+  --hup-anchor-sec <s>        HUP once the probe ran this long (default 3)
+  --hup-anchor-count <n>      ... and produced this many requests (default 200)
 
 Exit: 0 all pass | 100+N N cases failed | 2 usage | 3 preconditions
       | 4 dependency missing | 5 aborted
@@ -244,6 +261,8 @@ while [ $# -gt 0 ]; do
         --perf-threads)      PERF_THREADS="${2:-}"; shift 2 ;;
         --perf-conns)        PERF_CONNS="${2:-}"; shift 2 ;;
         --perf-duration)     PERF_DURATION="${2:-}"; shift 2 ;;
+        --hup-anchor-sec)    HUP_ANCHOR_SEC="${2:-}"; shift 2 ;;
+        --hup-anchor-count)  HUP_ANCHOR_COUNT="${2:-}"; shift 2 ;;
         -h|--help)           usage; exit 0 ;;
         *)                   die_usage "unknown option: $1" ;;
     esac
@@ -268,6 +287,7 @@ local -a values=()
 for n in TARGET_IP CLIENT CASES ROUNDS INTERVAL POLL WORKERS DRAIN_TIMEOUT STARTUP_WAIT \
     STREAM_MB RTE_FRESH_MIN SHUTDOWN_TIMEOUT BASELINE_DURATION GRACEFUL ZC_BUILD FAULT \
     FAULT_DELAY_MS PERF_THREADS PERF_CONNS PERF_DURATION \
+    HUP_ANCHOR_SEC HUP_ANCHOR_COUNT \
     NGINX_BIN FSTACK_TPL PROBE_DIR OUT BUILD_MANIFEST KERNEL_NIC_IP LCORE_MASK LCORE_LIST; do
     values+=("$n=${!n}")
 done
@@ -830,6 +850,9 @@ hup_once() { # conf
 # as a regression either, hence the dedicated code.
 do_hup_case() { # tag graceful shutdown_timeout probe-kind(none|stream|lc|cps) [check-mode]
     local tag="$1" g="$2" st="$3" probe="$4" mode="${5:-}"
+    # Reset the anchor: it is global so case_rt30/rt31 can quote it, and a
+    # leftover from the previous case must never be reported as this one's.
+    HUP_ANCHOR_LINE=""
     local conf out rc=0 nodata=0 wave=0 fetch=0 summary="no traffic probe"
     conf=$(gen_nginx_conf "$tag" "$st")
     push_probes || return 1
@@ -860,11 +883,19 @@ do_hup_case() { # tag graceful shutdown_timeout probe-kind(none|stream|lc|cps) [
         lc)
             launch_probe "$tag" 240 m4_lc.py --server "$TARGET_IP" --conns "$PERF_CONNS" \
                 --interval 0.1 --duration "$PERF_DURATION" --fresh 0.5 --timeout 2 || return 1
-            sleep 3 ;;
+            HUP_ANCHOR_LINE=$(wait_probe_progress LC_PROGRESS "$HUP_ANCHOR_SEC" \
+                "$HUP_ANCHOR_COUNT" 60) \
+                || { say "$tag: lc probe never reached the HUP anchor "
+                     "(${HUP_ANCHOR_SEC}s / ${HUP_ANCHOR_COUNT} requests)"; return 1; }
+            say "$tag: HUP anchored at: $HUP_ANCHOR_LINE" ;;
         cps)
             launch_probe "$tag" 240 m4_cps.py --server "$TARGET_IP" --threads "$PERF_THREADS" \
                 --duration "$PERF_DURATION" --timeout 2 || return 1
-            sleep 3 ;;
+            HUP_ANCHOR_LINE=$(wait_probe_progress CPS_PROGRESS "$HUP_ANCHOR_SEC" \
+                "$HUP_ANCHOR_COUNT" 60) \
+                || { say "$tag: cps probe never reached the HUP anchor "
+                     "(${HUP_ANCHOR_SEC}s / ${HUP_ANCHOR_COUNT} requests)"; return 1; }
+            say "$tag: HUP anchored at: $HUP_ANCHOR_LINE" ;;
     esac
 
     # Only the perf cases sample process CPU: the inventory walk would
@@ -875,7 +906,10 @@ do_hup_case() { # tag graceful shutdown_timeout probe-kind(none|stream|lc|cps) [
     esac
     [ "$probe" = none ] || probe_running || { say "$tag: probe not running before the reload"; rc=1; }
     hup_once "$conf" || rc=1
-    [ "$probe" = none ] || probe_running || { say "$tag: probe not running after the reload (window longer than the probe?)"; rc=1; }
+    [ "$probe" = none ] || probe_running \
+        || { say "$tag: probe not running after the reload (window longer than "
+                 "the probe? drain=${HUP_DRAIN}ms duration=${PERF_DURATION}s "
+                 "anchor=${HUP_ANCHOR_LINE:-none})"; rc=1; }
 
     # wait_client_summary reports 1 = no data (timeout / summary absent) and
     # 2 = the probe reported a summary but failed its own criterion. Only the
@@ -956,7 +990,7 @@ do_hup_case() { # tag graceful shutdown_timeout probe-kind(none|stream|lc|cps) [
 # (est_pps), not measured on the wire.
 case_rt30() {
     say "=== case rt30 (PT-NR-01: high CPS short connections) ==="
-    local hrc=0 rc=0 n rate cpu_per_1k est_pps crit meas
+    local hrc=0 rc=0 n rate cpu_per_1k est_pps crit meas anchor remaining
     crit="high-rate CPS: client fail=0 + reload complete + 6/6 FSM + workers back to $WORKERS"
     do_hup_case "rt30" 1 0 cps || hrc=$?
     if [ "$hrc" = "2" ]; then
@@ -968,7 +1002,13 @@ case_rt30() {
     rate=$(awk -v n="${n:-0}" -v d="$PERF_DURATION" 'BEGIN { if (n == 0 || d == 0) print "NA"; else printf "%.1f", n / d }')
     cpu_per_1k=$(awk -v c="$HUP_CPU_MS" -v n="${n:-0}" 'BEGIN { if (c == "NA" || n == 0) print "NA"; else printf "%.2f", c * 1000 / n }')
     est_pps=$(awk -v r="$rate" 'BEGIN { if (r == "NA") print "NA"; else printf "%.0f", r * 9 }')
-    meas="mode=cps threads=$PERF_THREADS duration=${PERF_DURATION}s n=${n:-NA} rate=${rate}/s cpu_ms=$HUP_CPU_MS cpu_per_1k=$cpu_per_1k est_pps=$est_pps drain=${HUP_DRAIN}ms fwd=${HUP_FWD} rel=${HUP_REL} $HUP_SUMMARY"
+    # Anchor evidence: where in the probe life the reload was sent, and how
+    # much of the probe was left at that moment (not after the reload).
+    anchor=$(printf '%s' "$HUP_ANCHOR_LINE" | sed -n 's/.*elapsed=\([0-9.]*\).*/\1/p')
+    [ -n "$anchor" ] || anchor="NA"
+    remaining=$(awk -v d="$PERF_DURATION" -v a="$anchor" \
+        'BEGIN { if (a == "NA") print "NA"; else printf "%.1f", d - a }')
+    meas="mode=cps threads=$PERF_THREADS duration=${PERF_DURATION}s n=${n:-NA} rate=${rate}/s cpu_ms=$HUP_CPU_MS cpu_per_1k=$cpu_per_1k est_pps=$est_pps drain=${HUP_DRAIN}ms fwd=${HUP_FWD} rel=${HUP_REL} anchor=${anchor}s remaining=${remaining}s $HUP_SUMMARY"
     if [ "$rc" = "0" ]; then
         record "rt30" "PASS" "$crit" "$meas"
     else
@@ -979,7 +1019,7 @@ case_rt30() {
 
 case_rt31() {
     say "=== case rt31 (PT-NR-02: high packet rate, long connections) ==="
-    local hrc=0 rc=0 n rate cpu_per_1k est_pps crit meas
+    local hrc=0 rc=0 n rate cpu_per_1k est_pps crit meas anchor remaining
     crit="high packet rate: fresh_fail=0 + at most one keep-alive closure per connection (G_old drains) + reload complete + 6/6 FSM + workers back to $WORKERS"
     do_hup_case "rt31" 1 0 lc perf || hrc=$?
     if [ "$hrc" = "2" ]; then
@@ -991,7 +1031,13 @@ case_rt31() {
     rate=$(awk -v n="${n:-0}" -v d="$PERF_DURATION" 'BEGIN { if (n == 0 || d == 0) print "NA"; else printf "%.1f", n / d }')
     cpu_per_1k=$(awk -v c="$HUP_CPU_MS" -v n="${n:-0}" 'BEGIN { if (c == "NA" || n == 0) print "NA"; else printf "%.2f", c * 1000 / n }')
     est_pps=$(awk -v r="$rate" 'BEGIN { if (r == "NA") print "NA"; else printf "%.0f", r * 3 }')
-    meas="mode=lc conns=$PERF_CONNS duration=${PERF_DURATION}s reqs=${n:-NA} rate=${rate}/s cpu_ms=$HUP_CPU_MS cpu_per_1k=$cpu_per_1k est_pps=$est_pps drain=${HUP_DRAIN}ms fwd=${HUP_FWD} rel=${HUP_REL} $HUP_SUMMARY"
+    # Anchor evidence: where in the probe life the reload was sent, and how
+    # much of the probe was left at that moment (not after the reload).
+    anchor=$(printf '%s' "$HUP_ANCHOR_LINE" | sed -n 's/.*elapsed=\([0-9.]*\).*/\1/p')
+    [ -n "$anchor" ] || anchor="NA"
+    remaining=$(awk -v d="$PERF_DURATION" -v a="$anchor" \
+        'BEGIN { if (a == "NA") print "NA"; else printf "%.1f", d - a }')
+    meas="mode=lc conns=$PERF_CONNS duration=${PERF_DURATION}s reqs=${n:-NA} rate=${rate}/s cpu_ms=$HUP_CPU_MS cpu_per_1k=$cpu_per_1k est_pps=$est_pps drain=${HUP_DRAIN}ms fwd=${HUP_FWD} rel=${HUP_REL} anchor=${anchor}s remaining=${remaining}s $HUP_SUMMARY"
     if [ "$rc" = "0" ]; then
         record "rt31" "PASS" "$crit" "$meas"
     else