From ccb2c7f7455162db7784d1f23c3b653d1777d942 Mon Sep 17 00:00:00 2001 From: John Safranek Date: Wed, 30 Sep 2026 10:12:51 -0700 Subject: [PATCH] scripts: capture socket state on a fwd-bulk stall When Phase 3 stops making progress, keep sampling the echoed byte count and the forward's sockets for up to 60 seconds before failing, so a CI failure shows whether the stall clears on its own (the kernel backing off a loopback retransmit) or the forward is hung. - print uname -r, then ss -tnoi for the entry, target and SSH ports every 10 seconds - list each process's state and wchan from /proc - end the failure message with "(it resumed)" or "(it hung)" --- scripts/fwd-bulk.test | 57 +++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 55 insertions(+), 2 deletions(-) diff --git a/scripts/fwd-bulk.test b/scripts/fwd-bulk.test index 50db3b03f..5e69b8ff3 100755 --- a/scripts/fwd-bulk.test +++ b/scripts/fwd-bulk.test @@ -100,6 +100,10 @@ echo_payload_size=0 echo_pause_after=1000000 echo_pause_secs=10 echo_stall_limit=20 +# Once the phase stalls, seconds to keep sampling its sockets before failing, +# and seconds between samples. +echo_capture_secs=60 +echo_capture_step=10 echo_entry_port=0 echo_target_port=0 # Phase 4. The second connection's payload, and seconds to wait for it. @@ -154,6 +158,46 @@ do_dump_logs() { done } +# A Phase 3 stall that clears on its own is the kernel backing off a +# retransmit on loopback. One that does not clear is the forward hung. Keep +# sampling the byte count and the phase's sockets for a while to tell which, +# and leave echo_moved at 1 if any bytes came back meanwhile. +do_echo_stall_capture() { + ssh_port=`cat "$echo_ready_file" 2>/dev/null` + filter="( sport = :$echo_entry_port or dport = :$echo_entry_port" + filter="$filter or sport = :$echo_target_port" + filter="$filter or dport = :$echo_target_port" + filter="$filter or sport = :$ssh_port or dport = :$ssh_port )" + echo_moved=0 + waited=0 + echo "--- stall capture, kernel `uname -r` ---" + while : + do + now=`wc -c < "$echo_received" 2>/dev/null | tr -d ' '` + [ -z "$now" ] && now=0 + [ "$now" -ne "$got" ] && echo_moved=1 + echo "--- ${waited}s after the stall: echoed $now ---" + command -v ss > /dev/null 2>&1 && ss -tnoi "$filter" 2>&1 + [ "$now" -ge "$echo_payload_size" ] && break + [ "$waited" -ge "$echo_capture_secs" ] && break + sleep $echo_capture_step + waited=`expr $waited + $echo_capture_step` + done + [ -d /proc ] || return + for entry in "echoserver:$echo_server_pid" "ssh:$echo_ssh_pid" \ + "target:$echo_target_pid" "client:$echo_client_pid" + do + pid=${entry#*:} + if [ ! -d "/proc/$pid" ] + then + echo "--- ${entry%%:*} pid $pid: exited" + continue + fi + echo "--- ${entry%%:*} pid $pid: `grep '^State' /proc/$pid/status \ + 2>/dev/null`, wchan `cat /proc/$pid/wchan 2>/dev/null`" + done +} + do_fail() { echo "$1" do_dump_logs @@ -509,8 +553,17 @@ do fi done -[ "$got" -eq "$echo_payload_size" ] \ - || do_fail "two-way forward stalled: sent $echo_payload_size, echoed $got" +if [ "$got" -ne "$echo_payload_size" ] +then + do_echo_stall_capture + if [ "$echo_moved" -eq 1 ] + then + do_fail "two-way forward stalled: sent $echo_payload_size, echoed\ + $got, then $now within ${waited}s more (it resumed)" + fi + do_fail "two-way forward stalled: sent $echo_payload_size, echoed $got,\ + nothing more in ${waited}s (it hung)" +fi cmp -s "$echo_payload" "$echo_received" \ || do_fail "the echoed data does not match what was sent"