From 5abb99ab86c1625f708f66f54fe2cdc1a63bff9d Mon Sep 17 00:00:00 2001
From: Yaro Kasear <git@kasear.net>
Date: Wed, 23 Apr 2025 11:57:29 -0500
Subject: [PATCH] Add timing logs to key operations in runtest.sh for better
 performance tracking

---
 runtest.sh | 26 +++++++++++++++++++++++++-
 1 file changed, 25 insertions(+), 1 deletion(-)

diff --git a/runtest.sh b/runtest.sh
index eed9097..1443bb8 100755
--- a/runtest.sh
+++ b/runtest.sh
@@ -1,6 +1,6 @@
 #!/bin/bash
 
-set -x
+# set -x
 set -euo pipefail
 trap 'echo "[✖] Execution halted at line $LINENO. An unexpected error occurred. Please contact your nearest bash therapist." >&2' ERR
 
@@ -26,7 +26,9 @@ SUDO_KEEPALIVE_PID=$!
 
 echo "Starting kismet..."
 
+SECONDS=0
 sudo systemctl start kismet
+echo "This took $SECONDS seconds."
 
 echo "Saturating the capture..."
 
@@ -34,7 +36,10 @@ sleep $LEAD_TIME
 
 # Function to get current TX failed count
 get_tx_failed() {
+  echo "Getting TX failed count..."
+  SECONDS=0
   iw dev $INTERFACE station dump | awk '/tx failed/ {print $3}'
+  echo "This took $SECONDS seconds."
 }
 
 freq_to_channel() {
@@ -77,8 +82,13 @@ run_iperf() {
   local result
 
   sleep 1s
+  SECONDS=0
+  echo "Running iperf3 $mode $direction to $target..."
   result=$(iperf3 "${args[@]}" -J >"$tmp_json" 2>"$tmp_err")
+  echo "This took $SECONDS seconds."
 
+  echo "Parsing iperf3 output..."
+  SECONDS=0
   parsed=$(jq -r '
   if .error then
     "iperf3-error"
@@ -91,6 +101,7 @@ run_iperf() {
   else
     "unexpected-format"
   end' "$tmp_json" || echo "execution-failed")
+  echo "This took $SECONDS seconds."
 
   if [[ "$parsed" == "iperf3-error" || "$parsed" == "no-end" || "$parsed" == "unexpected-format" || "$parsed" == "execution-failed" ]]; then
     timestamp=$(date -Iseconds)
@@ -106,7 +117,10 @@ run_iperf() {
 }
 
 # Start test email
+SECONDS=0
+echo "Sending start email..."
 echo -e "Subject: Test ${BOOT_ID} Started\n\nThis is to inform you that the tests have commenced for test ${BOOT_ID}." | msmtp "$RECIPIENT"
+echo "This took $SECONDS seconds."
 
 FAILED_START=$(get_tx_failed)
 
@@ -128,8 +142,10 @@ for ((COUNTER = 1; COUNTER <= NUM_TESTS; COUNTER++)); do
 
     speed_results=""
     for ((retry = 1; retry <= MAX_RETRIES; retry++)); do
+      SECONDS=0
       echo "    Attempting speed test (try $retry)..."
       speed_results=$(speedtest --secure --csv 2>/dev/null) || true
+      echo "    This took $SECONDS seconds."
 
       if [[ -n "$speed_results" ]]; then
         break
@@ -153,8 +169,11 @@ for ((COUNTER = 1; COUNTER <= NUM_TESTS; COUNTER++)); do
     freq=$(iw dev "$INTERFACE" link | awk '/freq:/ {print $2}')
     channel=$(freq_to_channel "$freq")
 
+    SECONDS=0
+    echo "    Running ping test..."
     packet_loss=$(ping -c "$PING_COUNT" -q "$PING_TARGET" | grep -oP '\d+(?=% packet loss)')
     jitter=$(ping -c "$PING_COUNT" "$PING_TARGET" | 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}')
+    echo "This took $SECONDS seconds."
 
     echo "    Running iperf3 tests..."
     LocalTCPUp=$(run_iperf "$IPERF_LOCAL_TARGET" tcp up)
@@ -193,7 +212,9 @@ if [ -z "$KISMET_LOG" ] || [ ! -f "$KISMET_LOG" ]; then
   exit 1
 fi
 
+SECONDS=0
 python3 "$SCRIPT_DIRECTORY/enrich.py" --csv "$TEST_FILE" --pcapng "$KISMET_LOG" --output "$ENRICHED_FILE"
+echo "This took $SECONDS seconds."
 
 # Final email with attachment(s)
 EMAIL_BODY="The test with UID ${BOOT_ID} is complete. Please collect the probe. Data is attached."
@@ -230,7 +251,10 @@ else
     ATTACHMENT_FLAGS+=("-a" "$file")
   done
 
+  echo "[+] Sending email to $RECIPIENT with attachments: ${ATTACHMENTS[*]}"
+  SECONDS=0
   echo "$EMAIL_BODY" | mutt -s "$EMAIL_SUBJECT" "${ATTACHMENT_FLAGS[@]}" -- "$RECIPIENT"
+  echo "This took $SECONDS seconds."
 fi
 echo "[+] Email sent to $RECIPIENT with attachments: ${ATTACHMENTS[*]}"