Created
August 29, 2025 01:31
-
-
Save Fail-Safe/184dfddbe35f3244a079819f3925add5 to your computer and use it in GitHub Desktop.
OpenWrt RRM Neighbor Report Timing Diagnostic & Hostapd RRM Neighbor Report own-entry race & leak harness
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| #!/bin/sh | |
| # phy_timing_diagnostic.sh - OpenWrt RRM Neighbor Report Timing Diagnostic | |
| # | |
| # Purpose: Diagnose timing differences between PHY interfaces for RRM rrm_nr_get_own | |
| # after wifi restart operations. Helps troubleshoot GitHub issue #16875. | |
| # | |
| # Usage: ./phy_timing_diagnostic.sh [test_type] [params...] | |
| # Test types: | |
| # comprehensive (default) - Full timing analysis with device info | |
| # monitor [duration] - Monitor ubus object registration for duration seconds | |
| # readiness [duration] - Test interface readiness for duration seconds | |
| # individual [iface] [attempts] - Test specific interface timing | |
| # all - Test all discovered interfaces with multiple restarts | |
| # discover - Just discover and list RRM-capable interfaces | |
| # | |
| # GitHub: https://github.com/openwrt/openwrt/issues/16875 | |
| log_with_timestamp() { | |
| echo "[$(date '+%Y-%m-%dT%H:%M:%S')] $*" | |
| } | |
| # Dynamically discover all hostapd interfaces with RRM support | |
| discover_rrm_interfaces() { | |
| discovered_interfaces="" | |
| log_with_timestamp "=== Discovering RRM-capable interfaces ===" | |
| # Get all hostapd ubus objects | |
| ubus_objects=$(ubus list | grep "^hostapd\\.phy" || true) | |
| if [ -z "$ubus_objects" ]; then | |
| log_with_timestamp "WARNING: No hostapd.phy* objects found in ubus" | |
| return 1 | |
| fi | |
| # Test each interface for rrm_nr_get_own method | |
| for obj in $ubus_objects; do | |
| iface=$(echo "$obj" | sed 's/^hostapd\.//') | |
| # Check if rrm_nr_get_own method exists | |
| methods=$(ubus -v list "$obj" 2>/dev/null | grep -o '"[^"]*"' | grep -o '[^"]*' || true) | |
| if echo "$methods" | grep -q "rrm_nr_get_own"; then | |
| log_with_timestamp "FOUND: $iface supports rrm_nr_get_own" | |
| discovered_interfaces="$discovered_interfaces $iface" | |
| else | |
| log_with_timestamp "SKIP: $iface missing rrm_nr_get_own method" | |
| fi | |
| done | |
| if [ -z "$discovered_interfaces" ]; then | |
| log_with_timestamp "ERROR: No RRM-capable interfaces found!" | |
| return 1 | |
| fi | |
| # Remove leading space | |
| discovered_interfaces=$(echo "$discovered_interfaces" | sed 's/^ *//') | |
| log_with_timestamp "RRM-capable interfaces: $discovered_interfaces" | |
| return 0 | |
| } | |
| # Get device hardware information | |
| get_device_info() { | |
| log_with_timestamp "=== Device Information ===" | |
| # Get device model | |
| model=$(cat /tmp/sysinfo/model 2>/dev/null || echo "Unknown") | |
| log_with_timestamp "Device: $model" | |
| # Get OpenWrt version | |
| version=$(cat /etc/openwrt_release 2>/dev/null | grep DISTRIB_DESCRIPTION | cut -d"'" -f2 || echo "Unknown") | |
| log_with_timestamp "OpenWrt: $version" | |
| # Get hostapd version and patches | |
| hostapd_version=$(hostapd -v 2>&1 | head -1 || echo "Unknown") | |
| log_with_timestamp "Hostapd: $hostapd_version" | |
| # Check for RRM patches | |
| if grep -q "rrm_nr_get_own" /usr/sbin/hostapd 2>/dev/null; then | |
| log_with_timestamp "RRM Patches: DETECTED" | |
| else | |
| log_with_timestamp "RRM Patches: NOT DETECTED" | |
| fi | |
| # PHY information | |
| phy_count=$(ls /sys/class/ieee80211/phy*/name 2>/dev/null | wc -l || echo 0) | |
| log_with_timestamp "PHY Count: $phy_count" | |
| if [ "$phy_count" -gt 0 ]; then | |
| for phy_file in /sys/class/ieee80211/phy*/name; do | |
| if [ -r "$phy_file" ]; then | |
| phy_name=$(cat "$phy_file") | |
| phy_path=$(dirname "$phy_file") | |
| phy_num=$(basename "$phy_path") | |
| log_with_timestamp " $phy_num: $phy_name" | |
| fi | |
| done | |
| fi | |
| } | |
| test_interface() { | |
| iface="$1" | |
| delay="$2" | |
| ubus call "hostapd.$iface" rrm_nr_get_own >/dev/null 2>&1 | |
| rc=$? | |
| if [ $rc -eq 0 ]; then | |
| log_with_timestamp "SUCCESS: $iface ready at T+${delay}s" | |
| return 0 | |
| else | |
| log_with_timestamp "FAILED: $iface not ready at T+${delay}s (rc=$rc)" | |
| return 1 | |
| fi | |
| } | |
| monitor_ubus_objects() { | |
| max_time="$1" | |
| log_with_timestamp "=== ubus Object Registration Timeline ===" | |
| for i in $(seq 0 $max_time); do | |
| count=$(ubus list | grep -c hostapd || echo 0) | |
| objects=$(ubus list | grep hostapd | tr '\n' ' ') | |
| log_with_timestamp "T+${i}s: $count hostapd objects: $objects" | |
| if [ $i -lt $max_time ]; then | |
| sleep 1 | |
| fi | |
| done | |
| } | |
| test_readiness_window() { | |
| max_delay="$1" | |
| interfaces="$2" | |
| log_with_timestamp "=== Interface Readiness Window Test ===" | |
| log_with_timestamp "Testing interfaces: $interfaces" | |
| for delay in $(seq 0 $max_delay); do | |
| log_with_timestamp "--- Testing at T+${delay}s ---" | |
| for iface in $interfaces; do | |
| test_interface "$iface" "$delay" | |
| done | |
| if [ $delay -lt $max_delay ]; then | |
| sleep 1 | |
| fi | |
| done | |
| } | |
| comprehensive_timing_test() { | |
| log_with_timestamp "=== Comprehensive PHY Timing Analysis ===" | |
| # Get device info first | |
| get_device_info | |
| # Discover interfaces | |
| if ! discover_rrm_interfaces; then | |
| log_with_timestamp "ERROR: Cannot discover RRM interfaces. Exiting." | |
| return 1 | |
| fi | |
| log_with_timestamp "Starting wifi restart..." | |
| # Perform wifi restart | |
| wifi | |
| start_time=$(date +%s) | |
| # Monitor for 10 seconds | |
| monitor_ubus_objects 10 & | |
| monitor_pid=$! | |
| # Test interface readiness with discovered interfaces | |
| test_readiness_window 10 "$discovered_interfaces" | |
| # Wait for monitor to complete | |
| wait $monitor_pid | |
| end_time=$(date +%s) | |
| duration=$((end_time - start_time)) | |
| log_with_timestamp "=== Test completed in ${duration}s ===" | |
| log_with_timestamp "=== Summary ===" | |
| log_with_timestamp "Please share this output in GitHub issue #16875" | |
| log_with_timestamp "https://github.com/openwrt/openwrt/issues/16875" | |
| } | |
| # Add detailed individual interface testing | |
| test_individual_interface_timing() { | |
| local iface="$1" | |
| local max_attempts="$2" | |
| log_with_timestamp "=== Individual Interface Timing: $iface ===" | |
| for attempt in $(seq 1 $max_attempts); do | |
| local start=$(date +%s%3N) # milliseconds | |
| ubus call "hostapd.$iface" rrm_nr_get_own >/dev/null 2>&1 | |
| local rc=$? | |
| local end=$(date +%s%3N) | |
| local duration=$((end - start)) | |
| if [ $rc -eq 0 ]; then | |
| log_with_timestamp "$iface attempt $attempt: SUCCESS (${duration}ms)" | |
| else | |
| log_with_timestamp "$iface attempt $attempt: FAILED rc=$rc (${duration}ms)" | |
| fi | |
| sleep 1 | |
| done | |
| } | |
| # Test all discovered interfaces individually | |
| test_all_interfaces_timing() { | |
| log_with_timestamp "=== Testing All Discovered Interfaces ===" | |
| # Get device info first | |
| get_device_info | |
| # Discover interfaces | |
| if ! discover_rrm_interfaces; then | |
| log_with_timestamp "ERROR: Cannot discover RRM interfaces. Exiting." | |
| return 1 | |
| fi | |
| restart_count=3 | |
| for iteration in $(seq 1 $restart_count); do | |
| log_with_timestamp "--- Restart iteration $iteration ---" | |
| wifi | |
| for iface in $discovered_interfaces; do | |
| test_individual_interface_timing "$iface" 5 | |
| done | |
| if [ $iteration -lt $restart_count ]; then | |
| log_with_timestamp "Waiting 3s before next iteration..." | |
| sleep 3 | |
| fi | |
| done | |
| } | |
| # Run based on argument | |
| case "${1:-comprehensive}" in | |
| "monitor") | |
| wifi && monitor_ubus_objects "${2:-10}" | |
| ;; | |
| "readiness") | |
| wifi && test_readiness_window "${2:-10}" | |
| ;; | |
| "individual") | |
| test_individual_interface_timing "${2:-phy1-ap0}" "${3:-5}" | |
| ;; | |
| "all") | |
| test_all_interfaces_timing | |
| ;; | |
| "discover") | |
| get_device_info | |
| discover_rrm_interfaces | |
| echo "Discovered RRM-capable interfaces: $discovered_interfaces" | |
| ;; | |
| "comprehensive"|*) | |
| comprehensive_timing_test | |
| ;; | |
| esac |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| #!/bin/sh | |
| # test_rrm_nr_init.sh - Hostapd RRM Neighbor Report own-entry race & leak harness | |
| # | |
| # Purpose: | |
| # 1. Detect intermittent UBUS_STATUS_NOT_FOUND from rrm_nr_get_own right after restart. | |
| # 2. Confirm patch (ordering fix) eliminates NOT_FOUND events entirely. | |
| # 3. Exercise repeated calls to ensure no memory growth / duplicate entries. | |
| # | |
| # Test Philosophy / Expectations: | |
| # Pre-fix (unpatched hostapd ordering window): | |
| # - At least some NOT_FOUND (>0) responses during the first rapid cycle(s) after each wifi reload. | |
| # - Aggregate NOT_FOUND (total_not_found) > 0 over all cycles. | |
| # Post-fix (patched ordering / ensure-on-enable): | |
| # - NOT_FOUND must be 0 in every rapid cycle (aggregate_not_found=0). | |
| # - Heavy call phase must also show 0 NOT_FOUND and stable RSS (memory). | |
| # | |
| # Pass / Fail Criteria: | |
| # PASS if: | |
| # - total_not_found == 0 | |
| # - memory RSS delta |after-before| <= MEM_DELTA_THRESHOLD_KB (default 64 kB) | |
| # FAIL if: | |
| # - Any NOT_FOUND observed (exit code 1) | |
| # - Memory delta exceeds threshold (exit code 2) *and* no NOT_FOUND (still signals investigation) | |
| # EXIT CODES: 0=pass, 1=NOT_FOUND, 2=memory delta, 3=setup error. | |
| # | |
| # Output Lines of Interest: | |
| # "Rapid cycle N summary: ... not_found=X" (per-cycle immediate race results) | |
| # "Aggregate rapid probe: total_not_found=Y" (overall race status) | |
| # "Hostapd RSS before/after" & delta (leak indicator) | |
| # "RESULT: PASS/FAIL" (final verdict) | |
| # | |
| # UBUS exit code mapping: | |
| # UBUS_STATUS_NOT_FOUND is 4; some older references reported 5. We treat 4 and 5 | |
| # equivalently for race detection. (5 may be UBUS_STATUS_NO_DATA in some versions.) | |
| # | |
| # Typical Pre-Fix Signature: | |
| # Rapid cycle 1 summary: ... not_found>0 (others maybe 0) | |
| # Aggregate rapid probe: total_not_found>0 | |
| # | |
| # Typical Post-Fix Signature: | |
| # All rapid cycles: not_found=0 | |
| # Aggregate rapid probe: total_not_found=0 | |
| # RSS delta small (often 0–a few kB; well below threshold) | |
| # | |
| # Tuning / Environment Variables: | |
| # IFACES="phy0-ap0 phy1-ap0" # override auto-detect | |
| # RESTARTS=8 # more restart cycles for confidence | |
| # RAPID_DURATION=3 # widen early window probing seconds | |
| # INITIAL_DELAY_MS=150 # shorten or lengthen post-restart pause | |
| # HEAVY_CALLS=5000 # deeper leak probe | |
| # MEM_DELTA_THRESHOLD_KB=96 # relax threshold if platform variance | |
| # LOG=/tmp/rrm_nr_test.log # capture output to file | |
| # VERIFY_PAYLOAD=1 # verify payload contains expected field after each rapid cycle | |
| # VERIFY_PATTERN='"value"' # grep pattern to look for in JSON when VERIFY_PAYLOAD=1 (default matches current JSON shape) | |
| # DECODE_NR=1 # when verifying, attempt to decode hex neighbor report element (best-effort summary) | |
| # | |
| # Interpreting Memory Delta: | |
| # Small fluctuations are normal due to allocations & freeing inside hostapd. | |
| # Consistent growth proportional to HEAVY_CALLS suggests a leak in ensure logic. | |
| # | |
| # Duplicate Self-Entry Check: | |
| # Script queries rrm_nr_list if present. Some builds may exclude self entry; COUNT=0 | |
| # alone is not a failure if rrm_nr_get_own succeeds. Adjust logic if list semantics change. | |
| # | |
| # Minimal Run: | |
| # sh test_rrm_nr_init.sh | |
| # | |
| # Example (Post-Fix PASS): | |
| # Aggregate rapid probe: total_calls=3000 total_not_found=0 total_other=0 | |
| # Hostapd RSS after: 10540kB (delta 0kB) | |
| # RESULT: PASS (no NOT_FOUND, memory stable) | |
| # | |
| # Environment: vanilla OpenWrt (BusyBox ash). No external deps beyond: ubus, hostapd_cli (optional), strings, grep, awk, date. | |
| # Output: human-readable log (stdout) + optional log file. | |
| # | |
| # Usage: | |
| # sh test_rrm_nr_init.sh # auto-detect hostapd.* objects | |
| # IFACES="wlan0 wlan1" sh test_rrM_nr_init.sh | |
| # Vars: | |
| # RAPID_DURATION=2 (seconds per restart rapid probe window) | |
| # RESTARTS=5 (number of wifi restarts for rapid probing) | |
| # HEAVY_CALLS=3000 (number of successive rrm_nr_get_own calls for leak test) | |
| # LOG=</path/to/log> (append full output to file) | |
| # WIFI_RELOAD_CMD="wifi reload" | |
| # WIFI_RESTART_CMD="wifi" | |
| # UBUS_TIMEOUT=1 # per-call timeout (seconds) for rapid probing (default 1 to avoid 30s hangs) | |
| # TIMING=1 # enable per-cycle timing metrics (elapsed, calls/sec, first_ok_s, first_nf_s) | |
| # VERIFY_DUMP=0 # when VERIFY_PAYLOAD=1, set to 1 to always dump first 300 chars of payload | |
| # | |
| # (See detailed expectations above: Pre-fix vs Post-fix, Pass/Fail criteria.) | |
| # | |
| # License: MIT (embed freely with patch discussion) | |
| set -u | |
| RAPID_DURATION=${RAPID_DURATION:-2} | |
| RESTARTS=${RESTARTS:-5} | |
| HEAVY_CALLS=${HEAVY_CALLS:-3000} | |
| LOG=${LOG:-} | |
| WIFI_RELOAD_CMD=${WIFI_RELOAD_CMD:-"wifi reload"} | |
| WIFI_RESTART_CMD=${WIFI_RESTART_CMD:-"wifi"} | |
| MEM_DELTA_THRESHOLD_KB=${MEM_DELTA_THRESHOLD_KB:-64} | |
| IFACES=${IFACES:-} | |
| INITIAL_DELAY_MS=${INITIAL_DELAY_MS:-300} # delay after restart before rapid probing (ms) | |
| VERIFY_PAYLOAD=${VERIFY_PAYLOAD:-0} # optional payload existence verification | |
| VERIFY_PATTERN=${VERIFY_PATTERN:-'"value"'} # pattern to consider payload valid | |
| TOTAL_AGGRESSIVE_FAILURES=0 # track race condition failures | |
| DECODE_NR=${DECODE_NR:-0} | |
| UBUS_TIMEOUT=${UBUS_TIMEOUT:-10} # shorten ubus call timeout (default ubus ~30s would stall rapid cycles) | |
| TIMING=${TIMING:-1} | |
| VERIFY_DUMP=${VERIFY_DUMP:-0} | |
| CLIENT_DEBUG=${CLIENT_DEBUG:-1} # enable detailed client-side debugging (0=off, 1=errors only, 2=all calls) | |
| AGGRESSIVE_TIMING=${AGGRESSIVE_TIMING:-0} # enable aggressive timing test (minimal delays, immediate calls) | |
| log() { | |
| ts="$(date -u +%Y-%m-%dT%H:%M:%SZ)" | |
| echo "[$ts] $*" | tee -a "$LOG" 2>/dev/null | |
| } | |
| need_cmd() { command -v "$1" >/dev/null 2>&1 || { log "ERROR: missing command $1"; exit 3; }; } | |
| for c in ubus grep awk date; do need_cmd $c; done | |
| # Helper: list and validate ubus objects | |
| check_ubus_objects() { | |
| available_objects=$(ubus list | grep '^hostapd\.' || true) | |
| if [ "$CLIENT_DEBUG" -ge 1 ]; then | |
| log "CLIENT_DEBUG: available ubus objects:" | |
| if [ -n "$available_objects" ]; then | |
| echo "$available_objects" | sed 's/^/ /' >&2 | |
| else | |
| log " (no hostapd.* objects found)" | |
| fi | |
| fi | |
| # Return just the objects list to stdout | |
| echo "$available_objects" | |
| } | |
| # Helper: test individual ubus object availability and show methods | |
| test_ubus_object() { | |
| obj="$1" | |
| methods=$(ubus -t 5 -v list "$obj" 2>/dev/null || true) | |
| if [ -n "$methods" ]; then | |
| # Debug: show what we actually got | |
| if [ "$CLIENT_DEBUG" -ge 2 ]; then | |
| log "CLIENT_DEBUG: raw methods output for $obj:" | |
| printf "%s\n" "$methods" | head -10 | while IFS= read -r line; do | |
| log " RAW: $line" | |
| done | |
| fi | |
| if echo "$methods" | grep -q "rrm_nr_get_own"; then | |
| [ "$CLIENT_DEBUG" -ge 1 ] && log "CLIENT_DEBUG: object $obj has rrm_nr_get_own method" | |
| return 0 # object exists and has the method | |
| else | |
| if [ "$CLIENT_DEBUG" -ge 1 ]; then | |
| log "CLIENT_DEBUG: object $obj exists but missing rrm_nr_get_own method" | |
| log "CLIENT_DEBUG: available methods for $obj:" | |
| echo "$methods" | grep -o '"[^"]*":' | sed 's/:$//' | head -10 | while IFS= read -r method; do | |
| log " $method" | |
| done | |
| fi | |
| return 2 # object exists but missing method | |
| fi | |
| else | |
| [ "$CLIENT_DEBUG" -ge 1 ] && log "CLIENT_DEBUG: object $obj does not exist or is not accessible" | |
| return 1 # object doesn't exist | |
| fi | |
| } | |
| # Detect hostapd ubus objects | |
| if [ -z "$IFACES" ]; then | |
| # Get available objects without debug output interference | |
| available_hostapd=$(ubus list | grep '^hostapd\.' || true) | |
| if [ "$CLIENT_DEBUG" -ge 1 ]; then | |
| log "CLIENT_DEBUG: available ubus objects:" | |
| if [ -n "$available_hostapd" ]; then | |
| echo "$available_hostapd" | sed 's/^/ /' | |
| else | |
| log " (no hostapd.* objects found)" | |
| fi | |
| fi | |
| IFACES=$(echo "$available_hostapd" | sed 's/^hostapd\.//' | tr '\n' ' ') | |
| fi | |
| [ -z "$IFACES" ] && { log "ERROR: no hostapd.* ubus objects found"; exit 3; } | |
| # Validate that our target interfaces actually exist and have the required method | |
| validated_ifaces="" | |
| for ifc in $IFACES; do | |
| obj="hostapd.$ifc" | |
| if test_ubus_object "$obj"; then | |
| validated_ifaces="$validated_ifaces$ifc " | |
| [ "$CLIENT_DEBUG" -ge 1 ] && log "CLIENT_DEBUG: validated interface $ifc (object $obj)" | |
| else | |
| [ "$CLIENT_DEBUG" -ge 1 ] && log "CLIENT_DEBUG: SKIPPING interface $ifc - object $obj not available or missing method" | |
| fi | |
| done | |
| if [ -z "$validated_ifaces" ]; then | |
| log "ERROR: no validated hostapd interfaces with rrm_nr_get_own method found" | |
| log "" | |
| log "DIAGNOSIS: hostapd objects exist but RRM neighbor report method is missing." | |
| log "This usually means RRM (Radio Resource Management) is not enabled." | |
| log "" | |
| log "TO FIX: Add these lines to your hostapd configuration:" | |
| log " rrm_neighbor_report=1" | |
| log " rrm_beacon_report=1" | |
| log "" | |
| log "Or check if your OpenWrt wireless config has:" | |
| log " option ieee80211k '1'" | |
| log "" | |
| exit 3 | |
| fi | |
| IFACES="$validated_ifaces" | |
| log "Test parameters: IFACES=$IFACES RAPID_DURATION=${RAPID_DURATION}s RESTARTS=$RESTARTS HEAVY_CALLS=$HEAVY_CALLS"; | |
| # Detect patch signature strings (optional heuristic) | |
| PATCH_SIG="$(strings /usr/sbin/hostapd 2>/dev/null | grep -E 'ensure own neighbor entry|rrm_nr_get_own: own neighbor entry missing' | sort -u)" | |
| if [ -n "$PATCH_SIG" ]; then | |
| log "hostapd contains candidate patch strings:"; echo "$PATCH_SIG" | sed 's/^/ /' | |
| else | |
| log "No patch signature strings detected (may be unpatched or stripped)." | |
| fi | |
| # Helper: sum hostapd RSS (kB) | |
| get_hostapd_rss_kb() { | |
| sum=0 | |
| for p in $(pidof hostapd 2>/dev/null); do | |
| rss=$(awk '/VmRSS:/ {print $2}' /proc/"$p"/status 2>/dev/null) | |
| [ -n "$rss" ] && sum=$((sum + rss)) | |
| done | |
| echo "$sum" | |
| } | |
| # Helper: check ubusd status | |
| check_ubusd_status() { | |
| ubusd_pid=$(pidof ubusd 2>/dev/null) | |
| if [ -n "$ubusd_pid" ]; then | |
| ubusd_rss=$(awk '/VmRSS:/ {print $2}' /proc/"$ubusd_pid"/status 2>/dev/null) | |
| log "CLIENT_DEBUG: ubusd pid=$ubusd_pid rss=${ubusd_rss:-unknown}kB" | |
| else | |
| log "CLIENT_DEBUG: ubusd not running!" | |
| fi | |
| } | |
| # Rapid probe after wifi restart | |
| rapid_probe_cycle() { | |
| cycle="$1" | |
| log "=== Rapid cycle $cycle: restarting wifi ($WIFI_RESTART_CMD) ===" | |
| # Check hostapd PIDs before restart | |
| hostapd_pids_before=$(pidof hostapd 2>/dev/null | wc -w) | |
| log "CLIENT_DEBUG: hostapd processes before restart: $hostapd_pids_before" | |
| restart_start=$(date +%s.%N 2>/dev/null || date +%s) | |
| eval "$WIFI_RESTART_CMD" >/dev/null 2>&1 & | |
| restart_pid=$! | |
| # Wait for restart command to complete | |
| wait $restart_pid | |
| restart_rc=$? | |
| restart_end=$(date +%s.%N 2>/dev/null || date +%s) | |
| # Calculate restart duration | |
| if [ "$restart_start" != "${restart_start#*.}" ]; then | |
| restart_duration=$(awk -v start="$restart_start" -v end="$restart_end" 'BEGIN{printf("%.3f", end-start)}') | |
| else | |
| restart_duration=$((restart_end - restart_start)) | |
| fi | |
| log "CLIENT_DEBUG: wifi restart completed rc=$restart_rc duration=${restart_duration}s" | |
| # Check hostapd PIDs after restart delay | |
| sleep 1 # Give hostapd time to start | |
| hostapd_pids_after=$(pidof hostapd 2>/dev/null | wc -w) | |
| log "CLIENT_DEBUG: hostapd processes after restart: $hostapd_pids_after" | |
| # Check what ubus objects are available after restart | |
| if [ "$CLIENT_DEBUG" -ge 1 ]; then | |
| # Give ubus minimal time to register objects after hostapd starts | |
| sleep 1 | |
| available_after_restart=$(ubus list | grep '^hostapd\.' || true) | |
| if [ -n "$available_after_restart" ]; then | |
| log "CLIENT_DEBUG: hostapd ubus objects available after restart:" | |
| echo "$available_after_restart" | sed 's/^/ /' | |
| # Test method availability for each detected interface | |
| for detected_ifc in $(echo "$available_after_restart" | sed 's/^hostapd\.//'); do | |
| obj="hostapd.$detected_ifc" | |
| if test_ubus_object "$obj"; then | |
| log "CLIENT_DEBUG: $obj has rrm_nr_get_own method available" | |
| else | |
| log "CLIENT_DEBUG: $obj missing rrm_nr_get_own method or not accessible" | |
| fi | |
| done | |
| else | |
| log "CLIENT_DEBUG: NO hostapd ubus objects found after restart!" | |
| # Try again after a short delay | |
| log "CLIENT_DEBUG: waiting additional 2 seconds for ubus registration..." | |
| sleep 2 | |
| available_after_restart=$(ubus list | grep '^hostapd\.' || true) | |
| if [ -n "$available_after_restart" ]; then | |
| log "CLIENT_DEBUG: hostapd ubus objects found after short wait:" | |
| echo "$available_after_restart" | sed 's/^/ /' | |
| else | |
| log "CLIENT_DEBUG: Still no hostapd ubus objects after short wait" | |
| # Show all ubus objects to debug | |
| all_objects=$(ubus list | head -20) | |
| log "CLIENT_DEBUG: sample of all available ubus objects:" | |
| echo "$all_objects" | sed 's/^/ /' | |
| fi | |
| fi # Check if our target interfaces are in the available list | |
| missing_interfaces="" | |
| for target_ifc in $IFACES; do | |
| if ! echo "$available_after_restart" | grep -q "^hostapd\.$target_ifc\$"; then | |
| missing_interfaces="$missing_interfaces$target_ifc " | |
| fi | |
| done | |
| if [ -n "$missing_interfaces" ]; then | |
| log "CLIENT_DEBUG: WARNING - target interfaces missing from ubus: $missing_interfaces" | |
| fi | |
| # If no target interfaces are available, abort this cycle early | |
| current_available_interfaces="" | |
| for target_ifc in $IFACES; do | |
| if echo "$available_after_restart" | grep -q "^hostapd\.$target_ifc\$"; then | |
| if test_ubus_object "hostapd.$target_ifc"; then | |
| current_available_interfaces="$current_available_interfaces$target_ifc " | |
| fi | |
| fi | |
| done | |
| if [ -z "$current_available_interfaces" ]; then | |
| log "CLIENT_DEBUG: ABORTING cycle $cycle - no target interfaces available with rrm_nr_get_own method" | |
| echo "0 0 0 0 0 0 0" # Return dummy values: ok nf timeout other total first_ok_s first_nf_s | |
| return | |
| else | |
| log "CLIENT_DEBUG: proceeding with available interfaces: $current_available_interfaces" | |
| if [ "$AGGRESSIVE_TIMING" = "1" ]; then | |
| log "CLIENT_DEBUG: AGGRESSIVE_TIMING enabled - testing immediately after ubus object detection" | |
| # Test ALL target interfaces immediately, even missing ones (to catch race conditions) | |
| aggressive_failures=0 | |
| for ifc in $IFACES; do | |
| obj="hostapd.$ifc" | |
| # Try the call regardless of whether we detected it in ubus list | |
| response=$(ubus -t 1 call "$obj" rrm_nr_get_own 2>&1) | |
| rc=$? | |
| if echo "$response" | grep -q "Command failed: Not found"; then | |
| log "CLIENT_DEBUG: AGGRESSIVE_TIMING RACE CONDITION DETECTED: $ifc returned 'Command failed: Not found'!" | |
| aggressive_failures=$((aggressive_failures + 1)) | |
| elif [ $rc -ne 0 ]; then | |
| log "CLIENT_DEBUG: AGGRESSIVE_TIMING $ifc failed: rc=$rc response='$response'" | |
| else | |
| log "CLIENT_DEBUG: AGGRESSIVE_TIMING $ifc succeeded immediately" | |
| fi | |
| done | |
| log "CLIENT_DEBUG: AGGRESSIVE_TIMING summary: $aggressive_failures race condition failures detected" | |
| TOTAL_AGGRESSIVE_FAILURES=$((TOTAL_AGGRESSIVE_FAILURES + aggressive_failures)) | |
| # Also test available interfaces with multiple rapid attempts | |
| for ifc in $current_available_interfaces; do | |
| obj="hostapd.$ifc" | |
| for attempt in 1 2 3; do | |
| response=$(ubus -t 2 call "$obj" rrm_nr_get_own 2>&1) | |
| rc=$? | |
| if [ $rc -ne 0 ]; then | |
| log "CLIENT_DEBUG: AGGRESSIVE_TIMING attempt $attempt for $ifc failed: rc=$rc response='$response'" | |
| else | |
| log "CLIENT_DEBUG: AGGRESSIVE_TIMING attempt $attempt for $ifc succeeded" | |
| break | |
| fi | |
| done | |
| done | |
| fi | |
| fi | |
| fi | |
| # Short initial delay (fractional sleep not always supported in BusyBox) | |
| if command -v usleep >/dev/null 2>&1; then | |
| usleep $((INITIAL_DELAY_MS * 1000)) | |
| else | |
| # Fallback: round milliseconds to whole seconds (minimum 1s if <1000) | |
| if [ "$INITIAL_DELAY_MS" -lt 1000 ]; then | |
| sleep 1 | |
| else | |
| sleep $((INITIAL_DELAY_MS / 1000)) | |
| fi | |
| fi | |
| start_ts=$(date +%s) | |
| end_time=$(( start_ts + RAPID_DURATION )) | |
| total=0; ok=0; nf=0; other=0; to=0 | |
| first_ok_s=""; first_nf_s="" | |
| while [ "$(date +%s)" -lt "$end_time" ]; do | |
| for ifc in $IFACES; do | |
| obj="hostapd.$ifc" | |
| # Use a short ubus timeout so missing / blocking methods don't inflate the rapid window | |
| call_start=$(date +%s.%N 2>/dev/null || date +%s) | |
| response=$(ubus -t "$UBUS_TIMEOUT" call "$obj" rrm_nr_get_own 2>&1) | |
| rc=$? | |
| call_end=$(date +%s.%N 2>/dev/null || date +%s) | |
| # Calculate duration (handle both nanosecond and second-only cases) | |
| if [ "$call_start" != "${call_start#*.}" ]; then | |
| # Nanosecond precision available | |
| duration=$(awk -v start="$call_start" -v end="$call_end" 'BEGIN{printf("%.3f", end-start)}') | |
| else | |
| # Second precision only | |
| duration=$((call_end - call_start)) | |
| fi | |
| total=$((total+1)) | |
| # Log detailed client-side information for debugging | |
| response_size=${#response} | |
| if [ "$CLIENT_DEBUG" -ge 1 ] && [ $rc -ne 0 ]; then | |
| # Log failed calls with details | |
| log "CLIENT_DEBUG: cycle=$cycle ifc=$ifc rc=$rc duration=${duration}s response_size=${response_size} response='${response}'" | |
| elif [ "$CLIENT_DEBUG" -ge 2 ]; then | |
| # Log all calls when debug level is high | |
| log "CLIENT_DEBUG: cycle=$cycle ifc=$ifc rc=$rc duration=${duration}s response_size=${response_size}" | |
| elif [ "$CLIENT_DEBUG" -ge 1 ] && [ $rc -eq 0 ] && [ "$response_size" -lt 10 ]; then | |
| # Log suspiciously small successful responses | |
| log "CLIENT_DEBUG: cycle=$cycle ifc=$ifc rc=$rc duration=${duration}s SMALL_RESPONSE size=${response_size} response='${response}'" | |
| fi | |
| case $rc in | |
| 0) | |
| ok=$((ok+1)) | |
| [ -z "$first_ok_s" ] && first_ok_s=$(( $(date +%s) - start_ts )) | |
| ;; | |
| 4|5) | |
| nf=$((nf+1)) | |
| [ -z "$first_nf_s" ] && first_nf_s=$(( $(date +%s) - start_ts )) | |
| ;; # 4=NOT_FOUND; 5=legacy/NO_DATA treated as miss | |
| 7) | |
| to=$((to+1)) | |
| ;; | |
| *) other=$((other+1));; | |
| esac | |
| done | |
| done | |
| elapsed=$(( $(date +%s) - start_ts )) | |
| [ $elapsed -le 0 ] && elapsed=1 | |
| if [ "$TIMING" = 1 ]; then | |
| cps=$(awk -v c=$total -v e=$elapsed 'BEGIN{ if(e>0) printf("%.1f", c/e); else print c }') | |
| extra=" elapsed=${elapsed}s cps=${cps}" | |
| [ -n "$first_ok_s" ] && extra="$extra first_ok_s=$first_ok_s" | |
| [ -n "$first_nf_s" ] && extra="$extra first_nf_s=$first_nf_s" | |
| else | |
| extra="" | |
| fi | |
| log "Rapid cycle $cycle summary: calls=$total ok=$ok not_found=$nf timeout=$to other=$other$extra" | |
| # Maintain original first 5 numeric fields for existing aggregate logic (cycle total ok nf other) | |
| echo "$cycle $total $ok $nf $other $to $elapsed" >> /tmp/rrm_nr_rapid_results | |
| if [ "$VERIFY_PAYLOAD" = 1 ]; then | |
| empty_cnt=0; bad_pattern_cnt=0; err_cnt=0 | |
| for ifc in $IFACES; do | |
| payload_cmd="ubus -t $UBUS_TIMEOUT call hostapd.$ifc rrm_nr_get_own" | |
| payload=$($payload_cmd 2>/dev/null); rc=$? | |
| [ "$VERIFY_DUMP" -eq 1 ] && echo "$payload" | head -c 300 | sed 's/^/ RAW: /' | |
| if [ $rc -ne 0 ]; then | |
| log "WARN: cycle=$cycle iface=$ifc verify rc=$rc (skipping pattern check)" | |
| err_cnt=$((err_cnt+1)) | |
| continue | |
| fi | |
| if [ -z "$payload" ]; then | |
| log "WARN: cycle=$cycle iface=$ifc payload empty" | |
| empty_cnt=$((empty_cnt+1)) | |
| continue | |
| fi | |
| echo "$payload" | grep -q "$VERIFY_PATTERN" || { | |
| log "WARN: cycle=$cycle iface=$ifc payload missing pattern $VERIFY_PATTERN" | |
| echo "$payload" | head -c 500 | sed 's/^/ JSON: /' | |
| bad_pattern_cnt=$((bad_pattern_cnt+1)) | |
| } | |
| if [ "$DECODE_NR" = 1 ]; then | |
| # Extract hex string (third array element) via simple awk/grep pipeline. | |
| hex=$(echo "$payload" | awk -F'"' '/value/ {getline;getline;getline; print}' | grep -o '[0-9a-f]\{32,\}' | head -n1 || true) | |
| if [ -n "$hex" ]; then | |
| hexlen=${#hex} | |
| # Basic Neighbor Report element interpretation (if length >= 13 bytes after hex -> 26 chars) | |
| # Layout (802.11-2020 9.4.2.36): BSSID(6) BSSID Info(4?2?) Regulatory Class(1) Channel(1) PHY Type(1) Optional subelements... | |
| # We just slice first typical fields. | |
| bssid=$(echo "$hex" | sed 's/\(..\)\(..\)\(..\)\(..\)\(..\)\(..\).*/\1:\2:\3:\4:\5:\6/') | |
| rest=$(echo "$hex" | sed 's/^\(..................................\)//') | |
| # Take next 4 bytes (8 chars) as bssid info (endianness not interpreted here) | |
| bssid_info=$(echo "$hex" | cut -c13-20) | |
| op_class=$(echo "$hex" | cut -c21-22) | |
| channel=$(echo "$hex" | cut -c23-24) | |
| phy_type=$(echo "$hex" | cut -c25-26) | |
| channel_dec=$(printf '%d' "0x$channel" 2>/dev/null || echo "$channel") | |
| log "DECODE: iface=$ifc hex_len_chars=$hexlen bssid=$bssid bssid_info=$bssid_info op_class=$op_class channel_dec=$channel_dec phy_type_hex=$phy_type" | |
| else | |
| log "DECODE: iface=$ifc no hex element extracted" | |
| fi | |
| fi | |
| done | |
| [ $empty_cnt -gt 0 ] && log "VERIFY: cycle=$cycle empty_payloads=$empty_cnt" | |
| [ $bad_pattern_cnt -gt 0 ] && log "VERIFY: cycle=$cycle missing_pattern=$bad_pattern_cnt" | |
| [ $err_cnt -gt 0 ] && log "VERIFY: cycle=$cycle rc_errors=$err_cnt" | |
| fi | |
| } | |
| : > /tmp/rrm_nr_rapid_results | |
| # Check initial ubusd status | |
| check_ubusd_status | |
| # Perform rapid cycles | |
| cycle=1 | |
| while [ $cycle -le "$RESTARTS" ]; do | |
| # Check ubusd status before each cycle | |
| check_ubusd_status | |
| rapid_probe_cycle $cycle | |
| cycle=$((cycle+1)) | |
| # Brief pause between cycles to let hostapd stabilize | |
| sleep 1 | |
| done | |
| # Check final ubusd status | |
| check_ubusd_status | |
| # Aggregate | |
| NF_TOTAL=$(awk '{s+=$4} END{print s}' /tmp/rrm_nr_rapid_results) | |
| OTHER_TOTAL=$(awk '{s+=$5} END{print s}' /tmp/rrm_nr_rapid_results) | |
| CALLS_TOTAL=$(awk '{s+=$2} END{print s}' /tmp/rrm_nr_rapid_results) | |
| log "Aggregate rapid probe: total_calls=$CALLS_TOTAL total_not_found=$NF_TOTAL total_other=$OTHER_TOTAL" | |
| # Heavy repeated calls (enable path runs inside getter each time) for leak detection | |
| log "=== Heavy call phase ($HEAVY_CALLS calls/interface) ===" | |
| RSS_BEFORE=$(get_hostapd_rss_kb) | |
| log "Hostapd RSS before: ${RSS_BEFORE}kB" | |
| for ifc in $IFACES; do | |
| i=1 | |
| while [ $i -le "$HEAVY_CALLS" ]; do | |
| ubus call hostapd."$ifc" rrm_nr_get_own >/dev/null 2>&1 || true | |
| i=$((i+1)) | |
| done | |
| log "Completed $HEAVY_CALLS calls for $ifc" | |
| done | |
| RSS_AFTER=$(get_hostapd_rss_kb) | |
| DELTA=$((RSS_AFTER - RSS_BEFORE)) | |
| log "Hostapd RSS after: ${RSS_AFTER}kB (delta ${DELTA}kB)" | |
| # Optional duplicate check via rrm_nr_list (if available) | |
| log "=== Duplicate self-entry check ===" | |
| for ifc in $IFACES; do | |
| if ubus call hostapd."$ifc" rrm_nr_list >/dev/null 2>&1; then | |
| BSSID=$(ubus call hostapd."$ifc" get_status 2>/dev/null | grep -o '"bssid" *: *"[0-9a-f:]*"' | head -n1 | sed 's/.*"\([0-9a-f:]*\)".*/\1/') | |
| COUNT=$(ubus call hostapd."$ifc" rrm_nr_list 2>/dev/null | grep -ci "$BSSID" || true) | |
| log "iface=$ifc self_bssid=$BSSID occurrences_in_rrm_nr_list=$COUNT" | |
| else | |
| log "iface=$ifc rrm_nr_list not supported (skipping)" | |
| fi | |
| done | |
| # Summarize & exit code logic | |
| log "=== Test Summary ===" | |
| log "Total ubus calls: $CALLS_TOTAL, NOT_FOUND: $NF_TOTAL, Other errors: $OTHER_TOTAL" | |
| if [ "$AGGRESSIVE_TIMING" = "1" ]; then | |
| log "Aggressive race condition failures: $TOTAL_AGGRESSIVE_FAILURES" | |
| fi | |
| log "Memory delta: ${DELTA}kB (threshold: ${MEM_DELTA_THRESHOLD_KB}kB)" | |
| EXIT=0 | |
| if [ "${NF_TOTAL}" != "0" ]; then | |
| log "FAIL: NOT_FOUND responses observed precluding fixed behavior" | |
| EXIT=1 | |
| fi | |
| if [ "$AGGRESSIVE_TIMING" = "1" ] && [ "${TOTAL_AGGRESSIVE_FAILURES}" != "0" ]; then | |
| log "FAIL: Aggressive timing race condition failures detected" | |
| EXIT=1 | |
| fi | |
| if [ $DELTA -gt "$MEM_DELTA_THRESHOLD_KB" ]; then | |
| log "WARN: memory delta ${DELTA}kB > threshold ${MEM_DELTA_THRESHOLD_KB}kB (possible growth)" | |
| [ $EXIT -eq 0 ] && EXIT=2 | |
| fi | |
| if [ $EXIT -eq 0 ]; then | |
| log "RESULT: PASS (no NOT_FOUND, memory stable)" | |
| else | |
| log "RESULT: FAIL (exit=$EXIT)" | |
| fi | |
| exit $EXIT |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment