Refactor iperf3 logging to remove unnecessary duration logs and improve clarity in warnings

This commit is contained in:
Yaro Kasear 2025-05-05 14:15:20 -05:00
parent 8038a46176
commit 3f5affa6fe

View file

@ -109,15 +109,12 @@ run_iperf() {
local timeout_duration=$((IPERF_DURATION + 20))
log "Running iperf3 $mode $direction to $target..."
SECONDS=0
if ! timeout "${timeout_duration}s" iperf3 "${args[@]}" >"$tmp_json" 2>"$tmp_err"; then
warn "iperf3 $mode $direction to $target failed or timed out after $SECONDS"
warn "iperf3 $mode $direction to $target failed or timed out"
echo "0"
return
fi
log "iperf3 completed in $SECONDS seconds"
SECONDS=0
local parsed
parsed=$(jq -r '
if .error then "iperf3-error"
@ -126,8 +123,6 @@ run_iperf() {
elif .end | has("sum") then .end.sum.bits_per_second
else "unexpected-format" end' "$tmp_json" 2>/dev/null || echo "execution-failed")
log "Parsed iperf3 result in $SECONDS seconds"
if [[ "$parsed" =~ ^(iperf3-error|no-end|unexpected-format|execution-failed)$ ]]; then
timestamp=$(date -Iseconds)
echo "$timestamp,iperf $mode $direction to $target failed with '$parsed'" >>"$FAILURE_LOG"
@ -142,15 +137,14 @@ run_iperf() {
}
# Send start email
SECONDS=0
echo -e "Subject: Test ${BOOT_ID} Started\n\nTest ${BOOT_ID} has commenced." | msmtp "$RECIPIENT"
log "Start email sent in $SECONDS seconds"
FAILED_START=$(get_tx_failed)
# CSV setup
TEST_HEADER="StartTimestamp,EndTimestamp,Link,Level,Noise,BSSID,TX Bitrate,RX Bitrate,$(speedtest --csv-header),TX Failures,Channel,Frequency,Packet Loss,Jitter,LocalTCPUp,LocalTCPDown,LocalUDPUp,LocalUDPDown,RemoteTCPUp,RemoteTCPDown,RemoteUDPUp,RemoteUDPDown"
LISTENER_HEADER="Timestamp,ClientsOnAP,ClientsOnChannel,APsOnChannel,AvgAPSignal,StrongestAPSignal,UnlinkedDevices,NumberofBSSIDsOnSSID,AvgSSIDSignal,MaxSSIDSignal,NumberofChannelsOnSSID,PacketCount,Deadpoints"
echo "Speedtest,LocalTCPUp,LocalTCPDown,LocalUDPUp,LocalUDPDown,RemoteTCPUp,RemoteTCPDown,RemoteUDPUp,RemoteUDPDown" > "${TEST_FILE}_durations.csv"
if [ ! -f "$TEST_FILE" ]; then
if [ "$LISTENER_ENABLED" -eq 1 ]; then
@ -192,48 +186,60 @@ for ((COUNTER = 1; COUNTER <= NUM_TESTS; COUNTER++)); do
speed_results=""
for ((retry = 1; retry <= MAX_RETRIES; retry++)); do
SECONDS=0
log " Speed test attempt $retry"
log "Speed test attempt $retry"
speed_results=$(speedtest --secure --csv 2>/dev/null || true)
log " Speed test took $SECONDS seconds"
$speedtest_duration=$SECONDS
[[ -n "$speed_results" ]] && break
warn " Speedtest failed. Retrying in $RETRY_DELAY seconds..."
warn "Speedtest failed. Retrying in $RETRY_DELAY seconds..."
echo "$(date -Iseconds),Speedtest failed on attempt $retry for test $COUNTER, sample $i" >> "$FAILURE_LOG"
sleep "$RETRY_DELAY"
done
if [[ -z "$speed_results" ]]; then
timestamp=$(date -Iseconds)
warn " Speedtest permanently failed. Skipping sample."
warn "Speedtest permanently failed. Skipping sample."
echo "$timestamp,Test $COUNTER,Sample $i" >>"$FAILURE_LOG"
$speedtest_duration=$SECONDS
continue
fi
SECONDS=0
log " Gathering TX failed count..."
FAILED_NOW=$(get_tx_failed)
FAILED_DELTA=$((FAILED_NOW - FAILED_START))
FAILED_START=$FAILED_NOW
log " TX count gathered in $SECONDS seconds"
freq=$(iw dev "$INTERFACE" link | awk '/freq:/ {print $2}')
channel=$(freq_to_channel "$freq")
SECONDS=0
log " Running ping test..."
ping_output=$(ping -c "$PING_COUNT" "$PING_TARGET")
packet_loss=$(echo "$ping_output" | grep -oP '\d+(?=% packet loss)')
jitter=$(echo "$ping_output" | grep "time=" | awk '{print $(NF-1)}' | sed 's/time=//g' | awk '{sum+=$1; sumsq+=$1*$1} END {if (NR>1) print sqrt(sumsq/NR - (sum/NR)**2); else print 0}')
log " Ping test took $SECONDS seconds"
log " Running iperf3 tests..."
SECONDS=0
LocalTCPUp=$(run_iperf "$IPERF_LOCAL_TARGET" tcp up)
localtcpup_duration=$SECONDS
SECONDS=0
LocalTCPDown=$(run_iperf "$IPERF_LOCAL_TARGET" tcp down)
localtcpdown_duration=$SECONDS
SECONDS=0
LocalUDPUp=$(run_iperf "$IPERF_LOCAL_TARGET" udp up)
localudpup_duration=$SECONDS
SECONDS=0
LocalUDPDown=$(run_iperf "$IPERF_LOCAL_TARGET" udp down)
localudpdown_duration=$SECONDS
SECONDS=0
RemoteTCPUp=$(run_iperf "$IPERF_REMOTE_TARGET" tcp up)
remotetcpup_duration=$SECONDS
SECONDS=0
RemoteTCPDown=$(run_iperf "$IPERF_REMOTE_TARGET" tcp down)
remotetcpdown_duration=$SECONDS
SECONDS=0
RemoteUDPUp=$(run_iperf "$IPERF_REMOTE_TARGET" udp up)
remoteudpup_duration=$SECONDS
SECONDS=0
RemoteUDPDown=$(run_iperf "$IPERF_REMOTE_TARGET" udp down)
remoteudpdown_duration=$SECONDS
if [ "$LISTENER_ENABLED" -eq 1 ]; then
if [ -n "${LISTENER_PID:-}" ]; then
@ -263,6 +269,8 @@ for ((COUNTER = 1; COUNTER <= NUM_TESTS; COUNTER++)); do
echo "$START_TIME,$END_TIME,$link_level_noise,$bssid_and_bitrate,$speed_results,$FAILED_DELTA,$channel,$freq,$packet_loss,$jitter,$LocalTCPUp,$LocalTCPDown,$LocalUDPUp,$LocalUDPDown,$RemoteTCPUp,$RemoteTCPDown,$RemoteUDPUp,$RemoteUDPDown" >> "$TEST_FILE"
fi
echo $START_TIME,$speedtest_duration,$localtcpup_duration,$localtcpdown_duration,$localudpup_duration,$localudpdown_duration,$remotetcpup_duration,$remotetcpdown_duration,$remoteudpup_duration,$remoteudpdown_duration" >> "${TEST_FILE}_durations.csv"
done
[[ "$COUNTER" -lt "$NUM_TESTS" ]] && log "Waiting $TIME_BETWEEN before next test..." && sleep "$TIME_BETWEEN"