From 3f5affa6fefb5be195231c14799ba235391a1bad Mon Sep 17 00:00:00 2001
From: Yaro Kasear <git@kasear.net>
Date: Mon, 5 May 2025 14:15:20 -0500
Subject: [PATCH] Refactor iperf3 logging to remove unnecessary duration logs
 and improve clarity in warnings

---
 runtest.sh | 42 +++++++++++++++++++++++++-----------------
 1 file changed, 25 insertions(+), 17 deletions(-)

diff --git a/runtest.sh b/runtest.sh
index 5ead78d..e005f2d 100755
--- a/runtest.sh
+++ b/runtest.sh
@@ -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"