From 06e55401aad5d40caaa4e3d6e070171c30b78242 Mon Sep 17 00:00:00 2001 From: "Ycarus (Yannick Chabanois)" Date: Thu, 1 Jun 2023 19:54:32 +0200 Subject: [PATCH 1/4] Fix & update sqm autorate --- luci-app-sqm-autorate/Makefile | 2 +- .../root/etc/init.d/sqm-autorate | 5 +- .../usr/share/sqm-autorate/cake-autorate.sh | 1674 ++++++++++------- .../sqm-autorate/cake-autorate_defaults.sh | 10 +- .../share/sqm-autorate/cake-autorate_lib.sh | 205 +- .../sqm-autorate/cake-autorate_template.sh | 61 +- tsping/Makefile | 38 + 7 files changed, 1111 insertions(+), 884 deletions(-) create mode 100644 tsping/Makefile diff --git a/luci-app-sqm-autorate/Makefile b/luci-app-sqm-autorate/Makefile index df160a3e5..51c3b4497 100644 --- a/luci-app-sqm-autorate/Makefile +++ b/luci-app-sqm-autorate/Makefile @@ -8,7 +8,7 @@ LUCI_DESCRIPTION:=Luci interface for the SQM scripts queue management package wi PKG_MAINTAINER:=Toke Høiland-Jørgensen -LUCI_DEPENDS:=+sqm-scripts +bash +LUCI_DEPENDS:=+sqm-scripts +bash +tsping LUCI_PKGARCH:=all include $(TOPDIR)/feeds/luci/luci.mk diff --git a/luci-app-sqm-autorate/root/etc/init.d/sqm-autorate b/luci-app-sqm-autorate/root/etc/init.d/sqm-autorate index 7ab556492..11b766808 100755 --- a/luci-app-sqm-autorate/root/etc/init.d/sqm-autorate +++ b/luci-app-sqm-autorate/root/etc/init.d/sqm-autorate @@ -29,8 +29,9 @@ _config_autorate() { config_get upload "$1" upload config_get max_upload "$1" max_upload [ "${min_upload}" == "0" ] || [ "${max_upload}" == "0" ] || [ "${upload}" == "0" ] && return - config_get interface "$1" interface - cp /usr/share/sqm-autorate/cake-autorate_template.sh /usr/share/sqm-autorate/cake-autorate_config.${interface}.sh +# config_get interface "$1" interface +# cp /usr/share/sqm-autorate/cake-autorate_template.sh /usr/share/sqm-autorate/cake-autorate_config.${interface}.sh + cp /usr/share/sqm-autorate/cake-autorate_template.sh /usr/share/sqm-autorate/cake-autorate_config.$1.sh } _launch_autorate() { diff --git a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate.sh b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate.sh index 426c08579..eda0680a4 100755 --- a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate.sh +++ b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate.sh @@ -14,13 +14,32 @@ # Author: @Lynx (OpenWrt forum) # Inspiration taken from: @moeller0 (OpenWrt forum) +cake_autorate_version="2.0.0" + +## cake-autorate uses multiple asynchronous processes including +## main - main process +## monitor_achieved_rates - monitor network transfer rates +## maintain_pingers - manage pingers and active reflectors +## parse_${pinger_binary} - control and parse ping responses +## parse_preprocessor - prepend field for parse_${pinger_binary} +## maintain_log_file - maintain and rotate log file +## +## IPC is facilitated via FIFOs in the form of anonymous pipes +## accessible via fds in the form: ${process_name_fd} +## thereby to enable transferring commands and data between processes + # Initialize file descriptors ## -1 signifies that the log file fd will not be used and ## that the log file will be written to directly log_fd=-1 -## ping_fd should be open for the duration of the script -## as it's integral to the operation of the script -exec {ping_fd}<> <(:) || true +exec {main_fd}<> <(:) || true +exec {monitor_achieved_rates_fd}<> <(:) || true +exec {maintain_pingers_fd}<> <(:) || true +# pinger_fds are set below in dependence upon ping binary and number of pingers + +# process pids are stored below in the form +# proc_pids['process_identifier']=${!} +declare -A proc_pids # Bash correctness options ## Disable globbing (expansion of *). @@ -32,6 +51,9 @@ set -u ## command exited with a non-zero status. set -o pipefail +## Errors are intercepted via intercept_stderr below +## and sent to the log file and system log + # Possible performance improvement export LC_ALL=C @@ -55,13 +77,25 @@ cleanup_and_killall() log_msg "INFO" "Killing all background processes and cleaning up temporary files." - proc_man_stop maintain_pingers - proc_man_stop monitor_achieved_rates - proc_man_stop maintain_log_file + printf "TERMINATE\n" >&"${maintain_pingers_fd}" + printf "TERMINATE\n" >&"${monitor_achieved_rates_fd}" [[ -d "${run_path}" ]] && rm -r "${run_path}" rmdir /var/run/cake-autorate 2>/dev/null + # give some time for processes to gracefully exit + sleep_s 1 + + # terminate any processes that remain, save for main and intercept_stderr + unset proc_pids[main] + intercept_stderr_pid="${proc_pids[intercept_stderr]}" + unset proc_pids[intercept_stderr] + terminate "${proc_pids[@]}" + + # restore original stderr, and terminate intercept_stderr + exec 2>&"${original_stderr_fd}" + terminate "${intercept_stderr_pid}" + log_msg "SYSLOG" "Stopped cake-autorate with PID: ${BASHPID} and config: ${config_path}" trap - INT TERM EXIT @@ -72,9 +106,9 @@ log_msg() { # send logging message to terminal, log file fifo, log file and/or system logger - local type=${1} - local msg=${2} - local instance_id=${instance_id:-"unknown"} + local type="${1}" + local msg="${2}" + local instance_id="${instance_id:-"unknown"}" case ${type} in @@ -122,7 +156,7 @@ print_headers() ((log_to_file)) && printf '%s\n' "${header}" >> "${log_file_path}" ((terminal)) && printf '%s\n' "${header}" - header="REFLECTOR_HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; REFLECTOR; DL_MIN_BASELINE_US; DL_BASELINE_US; DL_BASELINE_DELTA_US; DL_BASELINE_DELTA_THR_US; DL_MIN_DELTA_EWMA_US; DL_DELTA_EWMA_US; DL_DELTA_EWMA_DELTA_US; DL_DELTA_EWMA_DELTA_THR; UL_MIN_BASELINE_US; UL_BASELINE_US; UL_BASELINE_DELTA_US; UL_BASELINE_DELTA_THR_US; UL_MIN_DELTA_EWMA_US; UL_DELTA_EWMA_US; UL_DELTA_EWMA_DELTA_US; UL_DELTA_EWMA_DELTA_THR" + header="REFLECTOR_HEADER; LOG_DATETIME; LOG_TIMESTAMP; PROC_TIME_US; REFLECTOR; MIN_SUM_OWD_BASELINES_US; SUM_OWD_BASELINES_US; SUM_OWD_BASELINES_DELTA_US; SUM_OWD_BASELINES_DELTA_THR_US; MIN_DL_DELTA_EWMA_US; DL_DELTA_EWMA_US; DL_DELTA_EWMA_DELTA_US; DL_DELTA_EWMA_DELTA_THR; MIN_UL_DELTA_EWMA_US; UL_DELTA_EWMA_US; UL_DELTA_EWMA_DELTA_US; UL_DELTA_EWMA_DELTA_THR" ((log_to_file)) && printf '%s\n' "${header}" >> "${log_file_path}" ((terminal)) && printf '%s\n' "${header}" } @@ -141,19 +175,17 @@ rotate_log_file() ((output_processing_stats)) && print_headers } -generate_log_file_exporter() +generate_log_file_scripts() { - cat > "${run_path}/export_log_file" <<- EOT + cat > "${run_path}/log_file_export" <<- EOT #!/bin/bash - . "${PREFIX}/cake-autorate_lib.sh" - PROC_STATE_FILE="${run_path}/proc_state" - PROC_STATE_FILE_LOCK="${run_path}/proc_state.lock" - timeout_s=\${1:-20} - if ! proc_man_signal maintain_log_file "USR1" + if kill -USR1 "${proc_pids['maintain_log_file']}" then + printf "Successfully signalled maintain_log_file process to request log file export.\n" + else printf "ERROR: Failed to signal maintain_log_file process.\n" >&2 exit 1 fi @@ -178,7 +210,19 @@ generate_log_file_exporter() printf "\${log_file_export_path}\n" EOT - chmod +x "${run_path}/export_log_file" + cat > "${run_path}/log_file_rotate" <<- EOT + #!/bin/bash + + if kill -USR2 "${proc_pids['maintain_log_file']}" + then + printf "Successfully signalled maintain_log_file process to request log file rotation.\n" + else + printf "ERROR: Failed to signal maintain_log_file process.\n" >&2 + exit 1 + fi + EOT + + chmod +x "${run_path}/log_file_export" "${run_path}/log_file_rotate" } export_log_file() @@ -238,9 +282,11 @@ maintain_log_file() trap '' INT trap 'kill_maintain_log_file' TERM EXIT trap 'export_log_file' USR1 + trap 'rotate_log_file_signalled=1' USR2 log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" + rotate_log_file_signalled=0 t_log_file_start_us=${EPOCHREALTIME/./} get_log_file_size_bytes @@ -260,17 +306,21 @@ maintain_log_file() ((log_file_size_bytes=log_file_size_bytes+${#log_line}+1)) # Verify log file time < configured maximum - if (( (${EPOCHREALTIME/./}-t_log_file_start_us) > log_file_max_time_us )); then + if (( (${EPOCHREALTIME/./}-t_log_file_start_us) > log_file_max_time_us )) + then log_msg "DEBUG" "log file maximum time: ${log_file_max_time_mins} minutes has elapsed so rotating log file" break - fi - - if (( log_file_size_bytes > log_file_max_size_bytes )); then - + elif (( log_file_size_bytes > log_file_max_size_bytes )) + then log_file_size_KB=$((log_file_size_bytes/1024)) log_msg "DEBUG" "log file size: ${log_file_size_KB} KB has exceeded configured maximum: ${log_file_max_size_KB} KB so rotating log file" break + elif (( rotate_log_file_signalled )) + then + log_msg "DEBUG" "received log file rotation signal so rotating log file." + rotate_log_file_signalled=0 + break fi done @@ -285,64 +335,56 @@ maintain_log_file() get_next_shaper_rate() { - local min_shaper_rate_kbps=${1} - local base_shaper_rate_kbps=${2} - local max_shaper_rate_kbps=${3} - local achieved_rate_kbps=${4} - local load_condition=${5} - local t_next_rate_us=${6} - local -n t_last_bufferbloat_us=${7} - local -n t_last_decay_us=${8} - local -n shaper_rate_kbps=${9} + local direction="${1}" # 'dl' or 'ul' - case ${load_condition} in + case "${load_condition["${direction}"]}" in # upload Starlink satelite switching compensation, so drop down to minimum rate for upload through switching period ul*sss) - shaper_rate_kbps=${min_shaper_rate_kbps} + shaper_rate_kbps["${direction}"]="${min_shaper_rate_kbps[${direction}]}" ;; # download Starlink satelite switching compensation, so drop down to base rate for download through switching period dl*sss) - shaper_rate_kbps=$(( shaper_rate_kbps > base_shaper_rate_kbps ? base_shaper_rate_kbps : shaper_rate_kbps )) + shaper_rate_kbps["${direction}"]=$(( shaper_rate_kbps["${direction}"] > base_shaper_rate_kbps["${direction}"] ? base_shaper_rate_kbps["${direction}"] : shaper_rate_kbps["${direction}"] )) ;; # bufferbloat detected, so decrease the rate providing not inside bufferbloat refractory period *bb*) - if (( t_next_rate_us > (t_last_bufferbloat_us+bufferbloat_refractory_period_us) )); then - adjusted_achieved_rate_kbps=$(( (achieved_rate_kbps*achieved_rate_adjust_down_bufferbloat)/1000 )) - adjusted_shaper_rate_kbps=$(( (shaper_rate_kbps*shaper_rate_adjust_down_bufferbloat)/1000 )) - shaper_rate_kbps=$(( adjusted_achieved_rate_kbps > min_shaper_rate_kbps && adjusted_achieved_rate_kbps < adjusted_shaper_rate_kbps ? adjusted_achieved_rate_kbps : adjusted_shaper_rate_kbps )) - t_last_bufferbloat_us=${EPOCHREALTIME/./} + if (( t_start_us > (t_last_bufferbloat_us["${direction}"]+bufferbloat_refractory_period_us) )); then + adjusted_achieved_rate_kbps=$(( (achieved_rate_kbps["${direction}"]*achieved_rate_adjust_down_bufferbloat)/1000 )) + adjusted_shaper_rate_kbps=$(( (shaper_rate_kbps["${direction}"]*shaper_rate_adjust_down_bufferbloat)/1000 )) + shaper_rate_kbps["${direction}"]=$(( adjusted_achieved_rate_kbps > min_shaper_rate_kbps["${direction}"] && adjusted_achieved_rate_kbps < adjusted_shaper_rate_kbps ? adjusted_achieved_rate_kbps : adjusted_shaper_rate_kbps )) + t_last_bufferbloat_us["${direction}"]="${EPOCHREALTIME/./}" fi ;; # high load, so increase rate providing not inside bufferbloat refractory period *high*) - if (( t_next_rate_us > (t_last_bufferbloat_us+bufferbloat_refractory_period_us) )); then - shaper_rate_kbps=$(( (shaper_rate_kbps*shaper_rate_adjust_up_load_high)/1000 )) + if (( t_start_us > (t_last_bufferbloat_us["${direction}"]+bufferbloat_refractory_period_us) )); then + shaper_rate_kbps["${direction}"]=$(( (shaper_rate_kbps["${direction}"]*shaper_rate_adjust_up_load_high)/1000 )) fi ;; # low or idle load, so determine whether to decay down towards base rate, decay up towards base rate, or set as base rate *low*|*idle*) - if (( t_next_rate_us > (t_last_decay_us+decay_refractory_period_us) )); then + if (( t_start_us > (t_last_decay_us["${direction}"]+decay_refractory_period_us) )); then - if ((shaper_rate_kbps > base_shaper_rate_kbps)); then - decayed_shaper_rate_kbps=$(( (shaper_rate_kbps*shaper_rate_adjust_down_load_low)/1000 )) - shaper_rate_kbps=$(( decayed_shaper_rate_kbps > base_shaper_rate_kbps ? decayed_shaper_rate_kbps : base_shaper_rate_kbps)) - elif ((shaper_rate_kbps < base_shaper_rate_kbps)); then - decayed_shaper_rate_kbps=$(( (shaper_rate_kbps*shaper_rate_adjust_up_load_low)/1000 )) - shaper_rate_kbps=$(( decayed_shaper_rate_kbps < base_shaper_rate_kbps ? decayed_shaper_rate_kbps : base_shaper_rate_kbps)) + if ((shaper_rate_kbps["${direction}"] > base_shaper_rate_kbps["${direction}"])); then + decayed_shaper_rate_kbps=$(( (shaper_rate_kbps["${direction}"]*shaper_rate_adjust_down_load_low)/1000 )) + shaper_rate_kbps["${direction}"]=$(( decayed_shaper_rate_kbps > base_shaper_rate_kbps["${direction}"] ? decayed_shaper_rate_kbps : base_shaper_rate_kbps["${direction}"])) + elif ((shaper_rate_kbps["${direction}"] < base_shaper_rate_kbps["${direction}"])); then + decayed_shaper_rate_kbps=$(( (shaper_rate_kbps["${direction}"]*shaper_rate_adjust_up_load_low)/1000 )) + shaper_rate_kbps["${direction}"]=$(( decayed_shaper_rate_kbps < base_shaper_rate_kbps["${direction}"] ? decayed_shaper_rate_kbps : base_shaper_rate_kbps["${direction}"])) fi - t_last_decay_us=${EPOCHREALTIME/./} + t_last_decay_us["${direction}"]="${EPOCHREALTIME/./}" fi ;; *) - log_msg "ERROR" "unknown load condition: ${load_condition} in get_next_shaper_rate" + log_msg "ERROR" "unknown load condition: ${load_condition[${direction}]} in get_next_shaper_rate" exit 1 ;; esac # make sure to only return rates between cur_min_rate and cur_max_rate - ((shaper_rate_kbps < min_shaper_rate_kbps)) && shaper_rate_kbps=${min_shaper_rate_kbps} - ((shaper_rate_kbps > max_shaper_rate_kbps)) && shaper_rate_kbps=${max_shaper_rate_kbps} + ((shaper_rate_kbps["${direction}"] < min_shaper_rate_kbps["${direction}"])) && shaper_rate_kbps["${direction}"]="${min_shaper_rate_kbps[${direction}]}" + ((shaper_rate_kbps["${direction}"] > max_shaper_rate_kbps["${direction}"])) && shaper_rate_kbps["${direction}"]="${max_shaper_rate_kbps[${direction}]}" } monitor_achieved_rates() @@ -352,87 +394,110 @@ monitor_achieved_rates() # track rx and tx bytes transfered and divide by time since last update # to determine achieved dl and ul transfer rates - local rx_bytes_path=${1} - local tx_bytes_path=${2} - local monitor_achieved_rates_interval_us=${3} # (microseconds) + local rx_bytes_path="${1}" + local tx_bytes_path="${2}" + local monitor_achieved_rates_interval_us="${3}" # (microseconds) log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - compensated_monitor_achieved_rates_interval_us=${monitor_achieved_rates_interval_us} + compensated_monitor_achieved_rates_interval_us="${monitor_achieved_rates_interval_us}" [[ -f "${rx_bytes_path}" ]] && { read -r prev_rx_bytes < "${rx_bytes_path}"; } 2> /dev/null || prev_rx_bytes=0 [[ -f "${tx_bytes_path}" ]] && { read -r prev_tx_bytes < "${tx_bytes_path}"; } 2> /dev/null || prev_tx_bytes=0 + sleep_duration_s=0 + t_start_us=0 + + declare -A achieved_rate_kbps + declare -A load_percent + while true do - t_start_us=${EPOCHREALTIME/./} + t_start_us="${EPOCHREALTIME/./}" + + while read -r -t 0 -u "${monitor_achieved_rates_fd}" + do + unset command + read -r -u "${monitor_achieved_rates_fd}" -a command + case "${command[0]:-}" in + + SET_VAR) + if [[ "${command[1]:-}" && "${command[2]:-}" ]] + then + export -n "${command[1]}=${command[2]}" + fi + ;; + SET_ARRAY_ELEMENT) + if [[ "${command[1]:-}" && "${command[2]:-}" && "${command[3]:-}" ]] + then + declare -A "${command[1]}"+="(["${command[2]}"]="${command[3]}")" + fi + ;; + TERMINATE) + log_msg "DEBUG" "Terminating monitor_achieved_rates." + exit + ;; + *) + : + ;; + esac + done # If rx/tx bytes file exists, read it in, otherwise set to prev_bytes # This addresses interfaces going down and back up - [[ -f "${rx_bytes_path}" ]] && { read -r rx_bytes < "${rx_bytes_path}"; } 2> /dev/null || rx_bytes=${prev_rx_bytes} - [[ -f "${tx_bytes_path}" ]] && { read -r tx_bytes < "${tx_bytes_path}"; } 2> /dev/null || tx_bytes=${prev_tx_bytes} + [[ -f "${rx_bytes_path}" ]] && { read -r rx_bytes < "${rx_bytes_path}"; } 2> /dev/null || rx_bytes="${prev_rx_bytes}" + [[ -f "${tx_bytes_path}" ]] && { read -r tx_bytes < "${tx_bytes_path}"; } 2> /dev/null || tx_bytes="${prev_tx_bytes}" - dl_achieved_rate_kbps=$(( ((8000*(rx_bytes - prev_rx_bytes)) / compensated_monitor_achieved_rates_interval_us ) )) - ul_achieved_rate_kbps=$(( ((8000*(tx_bytes - prev_tx_bytes)) / compensated_monitor_achieved_rates_interval_us ) )) + achieved_rate_kbps[dl]=$(( ((8000*(rx_bytes - prev_rx_bytes)) / compensated_monitor_achieved_rates_interval_us ) )) + achieved_rate_kbps[ul]=$(( ((8000*(tx_bytes - prev_tx_bytes)) / compensated_monitor_achieved_rates_interval_us ) )) - ((dl_achieved_rate_kbps<0)) && dl_achieved_rate_kbps=0 - ((ul_achieved_rate_kbps<0)) && ul_achieved_rate_kbps=0 + ((achieved_rate_kbps[dl]<0)) && achieved_rate_kbps[dl]=0 + ((achieved_rate_kbps[ul]<0)) && achieved_rate_kbps[ul]=0 - printf '%s' "${dl_achieved_rate_kbps}" > "${run_path}/dl_achieved_rate_kbps" - printf '%s' "${ul_achieved_rate_kbps}" > "${run_path}/ul_achieved_rate_kbps" + printf "SET_ARRAY_ELEMENT achieved_rate_kbps dl %s\n" "${achieved_rate_kbps[dl]}" >&"${main_fd}" + printf "SET_ARRAY_ELEMENT achieved_rate_kbps ul %s\n" "${achieved_rate_kbps[ul]}" >&"${main_fd}" + + load_percent[dl]=$(( (100*achieved_rate_kbps[dl])/shaper_rate_kbps[dl] )) + load_percent[ul]=$(( (100*achieved_rate_kbps[ul])/shaper_rate_kbps[ul] )) + + for pinger_fd in "${pinger_fds[@]}" + do + printf "SET_ARRAY_ELEMENT load_percent dl %s\n" "${load_percent[dl]}" >&"${pinger_fd}" + printf "SET_ARRAY_ELEMENT load_percent ul %s\n" "${load_percent[ul]}" >&"${pinger_fd}" + done if ((output_load_stats)); then - concurrent_read_integer dl_shaper_rate_kbps "${run_path}/dl_shaper_rate_kbps" - concurrent_read_integer ul_shaper_rate_kbps "${run_path}/ul_shaper_rate_kbps" - printf -v load_stats '%s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${dl_achieved_rate_kbps}" "${ul_achieved_rate_kbps}" "${dl_shaper_rate_kbps}" "${ul_shaper_rate_kbps}" + printf -v load_stats '%s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${achieved_rate_kbps[dl]}" "${achieved_rate_kbps[ul]}" "${shaper_rate_kbps[dl]}" "${shaper_rate_kbps[ul]}" log_msg "LOAD" "${load_stats}" fi - prev_rx_bytes=${rx_bytes} - prev_tx_bytes=${tx_bytes} - - # read in the max_wire_packet_rtt_us - concurrent_read_integer max_wire_packet_rtt_us "${run_path}/max_wire_packet_rtt_us" - - compensated_monitor_achieved_rates_interval_us=$(( ((monitor_achieved_rates_interval_us>(10*max_wire_packet_rtt_us) )) ? monitor_achieved_rates_interval_us : 10*max_wire_packet_rtt_us )) + prev_rx_bytes="${rx_bytes}" + prev_tx_bytes="${tx_bytes}" + compensated_monitor_achieved_rates_interval_us=$(( monitor_achieved_rates_interval_us>(10*max_wire_packet_rtt_us) ? monitor_achieved_rates_interval_us : 10*max_wire_packet_rtt_us )) + sleep_remaining_tick_time "${t_start_us}" "${compensated_monitor_achieved_rates_interval_us}" + done } -get_loads() -{ - # read in the dl/ul achieved rates and determine the loads - - concurrent_read_integer dl_achieved_rate_kbps "${run_path}/dl_achieved_rate_kbps" - concurrent_read_integer ul_achieved_rate_kbps "${run_path}/ul_achieved_rate_kbps" - - dl_load_percent=$(( (100*dl_achieved_rate_kbps)/dl_shaper_rate_kbps )) - ul_load_percent=$(( (100*ul_achieved_rate_kbps)/ul_shaper_rate_kbps )) - - printf '%s' "${dl_load_percent}" > "${run_path}/dl_load_percent" - printf '%s' "${ul_load_percent}" > "${run_path}/ul_load_percent" -} classify_load() { # classify the load according to high/low/idle and add _delayed if delayed # thus ending up with high_delayed, low_delayed, etc. - local load_percent=${1} - local achieved_rate_kbps=${2} - local bufferbloat_detected=${3} - local -n load_condition=${4} + local direction="${1}" - if (( load_percent > high_load_thr_percent )); then - load_condition="high" - elif (( achieved_rate_kbps > connection_active_thr_kbps )); then - load_condition="low" + if (( load_percent["${direction}"] > high_load_thr_percent )); then + load_condition["${direction}"]="high" + elif (( achieved_rate_kbps["${direction}"] > connection_active_thr_kbps )); then + load_condition["${direction}"]="low" else - load_condition="idle" + load_condition["${direction}"]="idle" fi - ((bufferbloat_detected)) && load_condition=${load_condition}"_bb" + ((bufferbloat_detected["${direction}"])) && load_condition["${direction}"]="${load_condition[${direction}]}_bb" if ((sss_compensation)); then # shellcheck disable=SC2154 @@ -440,39 +505,33 @@ classify_load() do ((timestamp_usecs_past_minute=${EPOCHREALTIME/./}%60000000)) if (( (timestamp_usecs_past_minute > (sss_time_us-sss_compensation_pre_duration_us)) && (timestamp_usecs_past_minute < (sss_time_us+sss_compensation_post_duration_us)) )); then - load_condition=${load_condition}"_sss" + load_condition[direction]="${load_condition[direction]}_sss" break fi done fi + + load_condition["${direction}"]="${direction}_${load_condition[${direction}]}" } # MAINTAIN PINGERS + ASSOCIATED HELPER FUNCTIONS -# TSPING FUNCTIONS # - -kill_monitor_reflector_responses_tsping() +parse_preprocessor() { - trap - TERM EXIT - - log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - - # Store baselines and ewmas to files ready for next instance (e.g. after sleep) - for (( reflector=0; reflector "${run_path}/reflector_${reflectors[reflector]//./-}_dl_baseline_us" - [[ -n "${ul_owd_baselines_us[${reflectors[reflector]}]}" ]] && printf '%s' "${ul_owd_baselines_us[${reflectors[reflector]}]}" > "${run_path}/reflector_${reflectors[reflector]//./-}_ul_baseline_us" - [[ -n "${dl_owd_delta_ewmas_us[${reflectors[reflector]}]}" ]] && printf '%s' "${dl_owd_delta_ewmas_us[${reflectors[reflector]}]}" > "${run_path}/reflector_${reflectors[reflector]//./-}_dl_delta_ewma_us" - [[ -n "${ul_owd_delta_ewmas_us[${reflectors[reflector]}]}" ]] && printf '%s' "${ul_owd_delta_ewmas_us[${reflectors[reflector]}]}" > "${run_path}/reflector_${reflectors[reflector]//./-}_ul_delta_ewma_us" + printf "REFLECTOR_RESPONSE %s %s %s\n" "${timestamp}" "${remainder}" "${timestamp}" >&"${pinger_fds[pinger]}" done - - exit } -monitor_reflector_responses_tsping() +parse_tsping() { trap '' INT - trap kill_monitor_reflector_responses_tsping TERM EXIT + trap 'terminate "${pinger_pid}" "${parse_preprocessor_pid}"' TERM EXIT + + local parse_id="${1}" + local reflectors=("${@:2}") log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" @@ -481,266 +540,458 @@ monitor_reflector_responses_tsping() declare -A dl_owd_delta_ewmas_us declare -A ul_owd_delta_ewmas_us - t_start_us=${EPOCHREALTIME/./} - - # Read in baselines if they exist, else just set them to 1s (rapidly converges downwards on new OWDs) - for (( reflector=0; reflector < no_reflectors; reflector++ )) + for (( reflector=0; reflector= dl_owd_baselines_us[${reflector}] )) ? alpha_baseline_increase : alpha_baseline_decrease )) - ul_alpha=$(( (( ul_owd_us >= ul_owd_baselines_us[${reflector}] )) ? alpha_baseline_increase : alpha_baseline_decrease )) + while true + do + unset command + read -r -u "${pinger_fds[pinger]}" -a command + if [[ "${command-}" ]] + then + case "${command[0]}" in - ewma_iteration "${dl_owd_us}" "${dl_alpha}" "dl_owd_baselines_us[${reflector}]" - ewma_iteration "${ul_owd_us}" "${ul_alpha}" "ul_owd_baselines_us[${reflector}]" + REFLECTOR_RESPONSE) + read -r timestamp reflector seq _ _ _ _ _ dl_owd_ms ul_owd_ms checksum <<< "${command[@]:1}" + ;; - dl_owd_delta_us=$(( dl_owd_us - dl_owd_baselines_us[${reflector}] )) - ul_owd_delta_us=$(( ul_owd_us - ul_owd_baselines_us[${reflector}] )) + START_PINGER) + + exec {parse_preprocessor_fd}> >(parse_preprocessor) + parse_preprocessor_pid="${!}" + printf "SET_PROC_PID proc_pids %s %s\n" "${parse_id}_preprocessor" "${parse_preprocessor_pid}" >&"${main_fd}" + # accommodate present tsping interval/sleep handling to prevent ping flood with only one pinger + tsping_sleep_time=$(( no_pingers == 1 ? ping_response_interval_ms : 0 )) + ${ping_prefix_string} tsping ${ping_extra_args} --print-timestamps --machine-readable=' ' --sleep-time "${tsping_sleep_time}" --target-spacing "${ping_response_interval_ms}" "${reflectors[@]:0:${no_pingers}}" 2>/dev/null >&"${parse_preprocessor_fd}" & + pinger_pid="${!}" + printf "SET_PROC_PID proc_pids %s %s\n" "${parse_id}_pinger" "${pinger_pid}" >&"${main_fd}" + continue + ;; - concurrent_read_integer dl_load_percent "${run_path}/dl_load_percent" - concurrent_read_integer ul_load_percent "${run_path}/ul_load_percent" + KILL_PINGER) - if (( dl_load_percent < high_load_thr_percent && ul_load_percent < high_load_thr_percent)); then - ewma_iteration "${dl_owd_delta_us}" "${alpha_delta_ewma}" "dl_owd_delta_ewmas_us[${reflector}]" - ewma_iteration "${ul_owd_delta_us}" "${alpha_delta_ewma}" "ul_owd_delta_ewmas_us[${reflector}]" + terminate "${pinger_pid}" "${parse_preprocessor_pid}" + exec {parse_preprocessor_fd}>&- + continue + ;; + + SET_REFLECTORS) + + read -r -a reflectors <<< "${command[@]:1}" + log_msg "DEBUG" "Read in new reflectors: ${reflectors[*]}" + + for (( reflector=0; reflector&"${ping_fd}" + dl_owd_us="${dl_owd_ms}000" + ul_owd_us="${ul_owd_ms}000" - timestamp_us=${timestamp//[.]} + dl_owd_delta_us=$(( dl_owd_us - dl_owd_baselines_us[${reflector}] )) + ul_owd_delta_us=$(( ul_owd_us - ul_owd_baselines_us[${reflector}] )) - printf '%s' "${timestamp_us}" > "${run_path}/reflector_${reflector//./-}_last_timestamp_us" - - printf '%s' "${dl_owd_baselines_us[${reflector}]}" > "${run_path}/reflector_${reflector//./-}_dl_owd_baseline_us" - printf '%s' "${ul_owd_baselines_us[${reflector}]}" > "${run_path}/reflector_${reflector//./-}_ul_owd_baseline_us" - - printf '%s' "${dl_owd_delta_ewmas_us[${reflector}]}" > "${run_path}/reflector_${reflector//./-}_dl_owd_delta_ewma_us" - printf '%s' "${ul_owd_delta_ewmas_us[${reflector}]}" > "${run_path}/reflector_${reflector//./-}_ul_owd_delta_ewma_us" + # tsping employs ICMP type 13 and works with timestamps: Originate; Received; Transmit; and Finished, such that: + # + # dl_owd_us = Finished - Transmit + # ul_owd_us = Received - Originate + # + # The timestamps are supposed to relate to milliseconds past midnight UTC, albeit implementation varies, and, + # in any case, timestamps rollover at the local and/or remote ends, and the rollover may not be synchronized. + # + # Such an event would result in a huge spike in dl_owd_us or ul_owd_us and a lare delta relative to the baseline. + # + # So, to compensate, in the event that delta > 50 mins, immediately reset the baselines to the new dl_owd_us and ul_owd_us. + # + # Happilly, the sum of dl_owd_baseline_us and ul_owd_baseline_us will roughly equal rtt_baseline_us. + # And since Transmit is approximately equal to Received, RTT is approximately equal to Finished - Originate. + # And thus the sum of dl_owd_baseline_us and ul_owd_baseline_us should not be affected by the rollover/compensation. + # Hence working with this sum, rather than the individual components, is useful for the reflector health check in maintain_pingers(). - printf '%s' "${timestamp_us}" > "${run_path}/reflectors_last_timestamp_us" + if (( (${dl_owd_delta_us#-} + ${ul_owd_delta_us#-}) < 3000000000 )) + then + dl_alpha=$(( dl_owd_us >= dl_owd_baselines_us[${reflector}] ? alpha_baseline_increase : alpha_baseline_decrease )) + ul_alpha=$(( ul_owd_us >= ul_owd_baselines_us[${reflector}] ? alpha_baseline_increase : alpha_baseline_decrease )) + + ewma_iteration "${dl_owd_us}" "${dl_alpha}" "dl_owd_baselines_us[${reflector}]" + ewma_iteration "${ul_owd_us}" "${ul_alpha}" "ul_owd_baselines_us[${reflector}]" + + dl_owd_delta_us=$(( dl_owd_us - dl_owd_baselines_us[${reflector}] )) + ul_owd_delta_us=$(( ul_owd_us - ul_owd_baselines_us[${reflector}] )) + else + dl_owd_baselines_us[${reflector}]=${dl_owd_us} + ul_owd_baselines_us[${reflector}]=${ul_owd_us} + + dl_owd_delta_us=0 + ul_owd_delta_us=0 + fi + + if (( load_percent[dl] < high_load_thr_percent && load_percent[ul] < high_load_thr_percent)) + then + ewma_iteration "${dl_owd_delta_us}" "${alpha_delta_ewma}" "dl_owd_delta_ewmas_us[${reflector}]" + ewma_iteration "${ul_owd_delta_us}" "${alpha_delta_ewma}" "ul_owd_delta_ewmas_us[${reflector}]" + fi + + printf "REFLECTOR_RESPONSE %s %s %s %s %s %s %s %s %s %s %s\n" "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baselines_us[${reflector}]}" "${dl_owd_us}" "${dl_owd_delta_ewmas_us[${reflector}]}" "${dl_owd_delta_us}" "${ul_owd_baselines_us[${reflector}]}" "${ul_owd_us}" "${ul_owd_delta_ewmas_us[${reflector}]} ${ul_owd_delta_us}" >&"${main_fd}" + + timestamp_us="${timestamp//[.]}" + + printf "SET_ARRAY_ELEMENT dl_owd_baselines_us %s %s\n" "${reflector}" "${dl_owd_baselines_us[${reflector}]}" >&"${maintain_pingers_fd}" + printf "SET_ARRAY_ELEMENT ul_owd_baselines_us %s %s\n" "${reflector}" "${ul_owd_baselines_us[${reflector}]}" >&"${maintain_pingers_fd}" + + printf "SET_ARRAY_ELEMENT dl_owd_delta_ewmas_us %s %s\n" "${reflector}" "${dl_owd_delta_ewmas_us[${reflector}]}" >&"${maintain_pingers_fd}" + printf "SET_ARRAY_ELEMENT ul_owd_delta_ewmas_us %s %s\n" "${reflector}" "${ul_owd_delta_ewmas_us[${reflector}]}" >&"${maintain_pingers_fd}" + + printf "SET_ARRAY_ELEMENT reflector_last_timestamps_us %s %s\n" "${reflector}" "${timestamp_us}" >&"${maintain_pingers_fd}" + fi done } -# FPING FUNCTIONS # - -kill_monitor_reflector_responses_fping() -{ - trap - TERM EXIT - - log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - - # Store baselines and ewmas to files ready for next instance (e.g. after sleep) - for (( reflector=0; reflector "${run_path}/reflector_${reflectors[reflector]//./-}_baseline_us" - [[ -n "${rtt_delta_ewmas_us[${reflectors[reflector]}]}" ]] && printf '%s' "${rtt_delta_ewmas_us[${reflectors[reflector]}]}" > "${run_path}/reflector_${reflectors[reflector]//./-}_delta_ewma_us" - done - - exit -} - -monitor_reflector_responses_fping() +parse_fping() { trap '' INT - trap kill_monitor_reflector_responses_fping TERM EXIT + trap 'terminate "${pinger_pid}" "${parse_preprocessor_pid}"' TERM EXIT + + local parse_id="${1}" + + local reflectors=("${@:2}") log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" declare -A rtt_baselines_us declare -A rtt_delta_ewmas_us - t_start_us=${EPOCHREALTIME/./} - - # Read in baselines if they exist, else just set them to 1s (rapidly converges downwards on new RTTs) - for (( reflector=0; reflector < no_reflectors; reflector++ )) + for (( reflector=0; reflector/dev/null - do - t_start_us=${EPOCHREALTIME/./} + declare -A load_percent + load_percent[dl]=0 + load_percent[ul]=0 - [[ ${seq_rtt} =~ \[([0-9]+)\].*[[:space:]]([0-9]+)\.?([0-9]+)?[[:space:]]ms ]] || continue + t_start_us="${EPOCHREALTIME/./}" + + while true + do + unset command + read -r -u "${pinger_fds[pinger]}" -a command + if [[ "${command-}" ]] + then + case "${command[0]}" in - seq=${BASH_REMATCH[1]} + REFLECTOR_RESPONSE) - rtt_us=${BASH_REMATCH[3]}000 - rtt_us=$((${BASH_REMATCH[2]}000+10#${rtt_us:0:3})) + read -r timestamp reflector _ seq_rtt <<< "${command[@]:1}" + checksum="${command[@]: -1}" + ;; - alpha=$(( (( rtt_us >= rtt_baselines_us[${reflector}] )) ? alpha_baseline_increase : alpha_baseline_decrease )) + START_PINGER) - ewma_iteration "${rtt_us}" "${alpha}" "rtt_baselines_us[${reflector}]" + exec {parse_preprocessor_fd}> >(parse_preprocessor) + parse_preprocessor_pid="${!}" + printf "SET_PROC_PID proc_pids %s %s\n" "${parse_id}_preprocessor" "${parse_preprocessor_pid}" >&"${main_fd}" + ${ping_prefix_string} fping ${ping_extra_args} --timestamp --loop --period "${reflector_ping_interval_ms}" --interval "${ping_response_interval_ms}" --timeout 10000 "${reflectors[@]:0:${no_pingers}}" 2> /dev/null >&"${parse_preprocessor_fd}" & + pinger_pid="${!}" + printf "SET_PROC_PID proc_pids %s %s\n" "${parse_id}_pinger" "${pinger_pid}" >&"${main_fd}" + continue + ;; - rtt_delta_us=$(( rtt_us-rtt_baselines_us[${reflector}] )) + KILL_PINGER) - concurrent_read_integer dl_load_percent "${run_path}/dl_load_percent" - concurrent_read_integer ul_load_percent "${run_path}/ul_load_percent" + terminate "${pinger_pid}" "${parse_preprocessor_pid}" + exec {parse_preprocessor_fd}>&- + continue + ;; - if (( dl_load_percent < high_load_thr_percent && ul_load_percent < high_load_thr_percent)); then - ewma_iteration "${rtt_delta_us}" "${alpha_delta_ewma}" "rtt_delta_ewmas_us[${reflector}]" + SET_REFLECTORS) + + read -r -a reflectors <<< "${command[@]:1}" + log_msg "DEBUG" "Read in new reflectors: ${reflectors[*]}" + + for (( reflector=0; reflector= rtt_baselines_us[${reflector}] ? alpha_baseline_increase : alpha_baseline_decrease )) + + ewma_iteration "${rtt_us}" "${alpha}" "rtt_baselines_us[${reflector}]" + + rtt_delta_us=$(( rtt_us-rtt_baselines_us[${reflector}] )) + + if (( load_percent[dl] < high_load_thr_percent && load_percent[ul] < high_load_thr_percent)); then + ewma_iteration "${rtt_delta_us}" "${alpha_delta_ewma}" "rtt_delta_ewmas_us[${reflector}]" + fi + + dl_owd_baseline_us=$((rtt_baselines_us[${reflector}]/2)) + ul_owd_baseline_us="${dl_owd_baseline_us}" + + dl_owd_delta_ewma_us=$((rtt_delta_ewmas_us[${reflector}]/2)) + ul_owd_delta_ewma_us="${dl_owd_delta_ewma_us}" + + dl_owd_us=$((rtt_us/2)) + ul_owd_us="${dl_owd_us}" + + dl_owd_delta_us=$((rtt_delta_us/2)) + ul_owd_delta_us="${dl_owd_delta_us}" + + timestamp="${timestamp//[\[\]]}0" + + printf "REFLECTOR_RESPONSE %s %s %s %s %s %s %s %s %s %s %s\n" "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" >&"${main_fd}" + + timestamp_us="${timestamp//[.]}" + + printf "SET_ARRAY_ELEMENT dl_owd_baselines_us %s %s\n" "${reflector}" "${dl_owd_baseline_us}" >&"${maintain_pingers_fd}" + printf "SET_ARRAY_ELEMENT ul_owd_baselines_us %s %s\n" "${reflector}" "${ul_owd_baseline_us}" >&"${maintain_pingers_fd}" + + printf "SET_ARRAY_ELEMENT dl_owd_delta_ewmas_us %s %s\n" "${reflector}" "${dl_owd_delta_ewma_us}" >&"${maintain_pingers_fd}" + printf "SET_ARRAY_ELEMENT ul_owd_delta_ewmas_us %s %s\n" "${reflector}" "${ul_owd_delta_ewma_us}" >&"${maintain_pingers_fd}" + + printf "SET_ARRAY_ELEMENT reflector_last_timestamps_us %s %s\n" "${reflector}" "${timestamp_us}" >&"${maintain_pingers_fd}" fi - - dl_owd_baseline_us=$((rtt_baselines_us[${reflector}]/2)) - ul_owd_baseline_us=${dl_owd_baseline_us} - - dl_owd_delta_ewma_us=$((rtt_delta_ewmas_us[${reflector}]/2)) - ul_owd_delta_ewma_us=${dl_owd_delta_ewma_us} - - dl_owd_us=$((rtt_us/2)) - ul_owd_us=${dl_owd_us} - - dl_owd_delta_us=$((rtt_delta_us/2)) - ul_owd_delta_us=${dl_owd_delta_us} - - timestamp=${timestamp//[\[\]]}0 - - printf '%s %s %s %s %s %s %s %s %s %s %s\n' "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" >&"${ping_fd}" - - timestamp_us=${timestamp//[.]} - - printf '%s' "${timestamp_us}" > "${run_path}/reflector_${reflector//./-}_last_timestamp_us" - - printf '%s' "${dl_owd_baseline_us}" > "${run_path}/reflector_${reflector//./-}_dl_owd_baseline_us" - printf '%s' "${ul_owd_baseline_us}" > "${run_path}/reflector_${reflector//./-}_ul_owd_baseline_us" - - printf '%s' "${dl_owd_delta_ewma_us}" > "${run_path}/reflector_${reflector//./-}_dl_owd_delta_ewma_us" - printf '%s' "${ul_owd_delta_ewma_us}" > "${run_path}/reflector_${reflector//./-}_ul_owd_delta_ewma_us" - - printf '%s' "${timestamp_us}" > "${run_path}/reflectors_last_timestamp_us" - - done 2>/dev/null + done } - # IPUTILS-PING FUNCTIONS - -kill_monitor_reflector_responses_ping() -{ - trap - TERM EXIT - log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - [[ -n "${rtt_baseline_us:-}" ]] && printf '%s' "${rtt_baseline_us}" > "${run_path}/reflector_${reflectors[pinger]//./-}_baseline_us" - [[ -n "${rtt_delta_ewma_us:-}" ]] && printf '%s' "${rtt_delta_ewma_us}" > "${run_path}/reflector_${reflectors[pinger]//./-}_delta_ewma_us" - exit -} - -monitor_reflector_responses_ping() +parse_ping() { trap '' INT - trap kill_monitor_reflector_responses_ping TERM EXIT + trap 'terminate "${pinger_pid}" "${parse_preprocessor_pid}"' TERM EXIT # ping reflector, maintain baseline and output deltas to a common fifo - local pinger=${1} + local parse_id="${1}" + local reflector="${2}" log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - if [[ -f "${run_path}/reflector_${reflectors[pinger]//./-}_baseline_us" ]]; then - read -r rtt_baseline_us < "${run_path}/reflector_${reflectors[pinger]//./-}_baseline_us" - else - rtt_baseline_us=100000 - fi + declare -A rtt_baselines_us + declare -A rtt_delta_ewmas_us - if [[ -f "${run_path}/reflector_${reflectors[pinger]//./-}_delta_ewma_us" ]]; then - read -r rtt_delta_ewma_us < "${run_path}/reflector_${reflectors[pinger]//./-}_delta_ewma_us" - else - rtt_delta_ewma_us=0 - fi + rtt_baselines_us[${reflector}]=100000 + rtt_delta_ewmas_us[${reflector}]=0 - while read -r -u "${pinger_fds[pinger]}" timestamp _ _ _ reflector seq_rtt 2>/dev/null + declare -A load_percent + load_percent[dl]=0 + load_percent[ul]=0 + + while true do - # If no match then skip onto the next one - [[ ${seq_rtt} =~ icmp_[s|r]eq=([0-9]+).*time=([0-9]+)\.?([0-9]+)?[[:space:]]ms ]] || continue + unset command + read -r -u "${pinger_fds[pinger]}" -a command + if [[ "${command-}" ]] + then + case "${command[0]}" in - seq=${BASH_REMATCH[1]} + REFLECTOR_RESPONSE) - rtt_us=${BASH_REMATCH[3]}000 - rtt_us=$((${BASH_REMATCH[2]}000+10#${rtt_us:0:3})) + read -r timestamp _ _ _ reflector seq_rtt <<< "${command[@]:1}" + checksum="${command[@]: -1}" + ;; - reflector=${reflector//:/} + START_PINGER) - alpha=$(( (( rtt_us >= rtt_baseline_us )) ? alpha_baseline_increase : alpha_baseline_decrease )) + exec {parse_preprocessor_fd}> >(parse_preprocessor) + parse_preprocessor_pid="${!}" + printf "SET_PROC_PID %s %s\n" "proc_pids ${parse_id}_preprocessor" "${parse_preprocessor_pid}" >&"${main_fd}" + ${ping_prefix_string} ping ${ping_extra_args} -D -i "${reflector_ping_interval_s}" "${reflector}" 2> /dev/null >&"${parse_preprocessor_fd}" & + pinger_pid="${!}" + printf "SET_PROC_PID proc_pids %s %s\n" "${parse_id}_pinger" "${pinger_pid}" >&"${main_fd}" + continue + ;; - ewma_iteration "${rtt_us}" "${alpha}" rtt_baseline_us - - rtt_delta_us=$(( rtt_us-rtt_baseline_us )) + KILL_PINGER) - concurrent_read_integer dl_load_percent "${run_path}/dl_load_percent" - concurrent_read_integer ul_load_percent "${run_path}/ul_load_percent" + terminate "${pinger_pid}" "${parse_preprocessor_pid}" + exec {parse_preprocessor_fd}>&- + continue + ;; - if (( dl_load_percent < high_load_thr_percent && ul_load_percent < high_load_thr_percent )); then - ewma_iteration "${rtt_delta_us}" "${alpha_delta_ewma}" rtt_delta_ewma_us + SET_REFLECTOR) + + if [[ "${command[1]:-}" ]] + then + reflector="${command[1]}" + log_msg "DEBUG" "Read in new reflector: ${reflector}" + rtt_baselines_us[${reflector}]="${rtt_baselines_us[${reflector}]:-100000}" + rtt_delta_ewmas_us[${reflector}]="${rtt_delta_ewmas_us[${reflector}]:-0}" + continue + fi + ;; + + SET_VAR) + + if [[ "${command[1]:-}" && "${command[2]:-}" ]] + then + export -n "${command[1]}=${command[2]}" + fi + continue + ;; + + SET_ARRAY_ELEMENT) + + if [[ "${command[1]:-}" && "${command[2]:-}" && "${command[3]:-}" ]] + then + declare -A "${command[1]}"+="(["${command[2]}"]="${command[3]}")" + fi + ;; + + TERMINATE) + + log_msg "DEBUG" "Terminating parse_ping." + exit + ;; + + *) + + : + ;; + + esac + fi + + if [[ "${timestamp:-}" && "${reflector:-}" && "${seq_rtt:-}" && "${checksum:-}" ]] + then + [[ "${checksum}" == "${timestamp}" ]] + # If no match then skip onto the next one + [[ "${seq_rtt}" =~ icmp_[s|r]eq=([0-9]+).*time=([0-9]+)\.?([0-9]+)?[[:space:]]ms ]] || continue + + seq=${BASH_REMATCH[1]} + + rtt_us=${BASH_REMATCH[3]}000 + rtt_us=$((${BASH_REMATCH[2]}000+10#${rtt_us:0:3})) + + reflector=${reflector//:/} + + alpha=$(( rtt_us >= rtt_baselines_us[${reflector}] ? alpha_baseline_increase : alpha_baseline_decrease )) + + ewma_iteration "${rtt_us}" "${alpha}" "rtt_baselines_us[${reflector}]" + + rtt_delta_us=$(( rtt_us-rtt_baselines_us[${reflector}] )) + + if (( load_percent[dl] < high_load_thr_percent && load_percent[ul] < high_load_thr_percent )); then + ewma_iteration "${rtt_delta_us}" "${alpha_delta_ewma}" "rtt_delta_ewmas_us[${reflector}]" + fi + + dl_owd_baseline_us=$((rtt_baselines_us[${reflector}]/2)) + ul_owd_baseline_us=${dl_owd_baseline_us} + + dl_owd_delta_ewma_us=$((rtt_delta_ewmas_us[${reflector}]/2)) + ul_owd_delta_ewma_us=${dl_owd_delta_ewma_us} + + dl_owd_us=$((rtt_us/2)) + ul_owd_us="${dl_owd_us}" + + dl_owd_delta_us=$((rtt_delta_us/2)) + ul_owd_delta_us="${dl_owd_delta_us}" + + timestamp="${timestamp//[\[\]]}" + + printf "REFLECTOR_RESPONSE %s %s %s %s %s %s %s %s %s %s %s\n" "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" >&"${main_fd}" + + timestamp_us="${timestamp//[.]}" + + printf "SET_ARRAY_ELEMENT dl_owd_baselines_us %s %s\n" "${reflector}" "${dl_owd_baseline_us}" >&"${maintain_pingers_fd}" + printf "SET_ARRAY_ELEMENT ul_owd_baselines_us %s %s\n" "${reflector}" "${ul_owd_baseline_us}" >&"${maintain_pingers_fd}" + + printf "SET_ARRAY_ELEMENT dl_owd_delta_ewmas_us %s %s\n" "${reflector}" "${dl_owd_delta_ewma_us}" >&"${maintain_pingers_fd}" + printf "SET_ARRAY_ELEMENT ul_owd_delta_ewmas_us %s %s\n" "${reflector}" "${ul_owd_delta_ewma_us}" >&"${maintain_pingers_fd}" + + printf "SET_ARRAY_ELEMENT reflector_last_timestamps_us %s %s\n" "${reflector}" "${timestamp_us}" >&"${maintain_pingers_fd}" fi - - dl_owd_baseline_us=$((rtt_baseline_us/2)) - ul_owd_baseline_us=${dl_owd_baseline_us} - - dl_owd_delta_ewma_us=$((rtt_delta_ewma_us/2)) - ul_owd_delta_ewma_us=${dl_owd_delta_ewma_us} - - dl_owd_us=$((rtt_us/2)) - ul_owd_us=${dl_owd_us} - - dl_owd_delta_us=$((rtt_delta_us/2)) - ul_owd_delta_us=${dl_owd_delta_us} - - timestamp=${timestamp//[\[\]]} - - printf '%s %s %s %s %s %s %s %s %s %s %s\n' "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" >&"${ping_fd}" - - timestamp_us=${timestamp//[.]} - - printf '%s' "${timestamp_us}" > "${run_path}/reflector_${reflector//./-}_last_timestamp_us" - - printf '%s' "${dl_owd_baseline_us}" > "${run_path}/reflector_${reflector//./-}_dl_owd_baseline_us" - printf '%s' "${ul_owd_baseline_us}" > "${run_path}/reflector_${reflector//./-}_ul_owd_baseline_us" - - printf '%s' "${dl_owd_delta_ewma_us}" > "${run_path}/reflector_${reflector//./-}_dl_owd_delta_ewma_us" - printf '%s' "${ul_owd_delta_ewma_us}" > "${run_path}/reflector_${reflector//./-}_ul_owd_delta_ewma_us" - - printf '%s' "${timestamp_us}" > "${run_path}/reflectors_last_timestamp_us" - - done 2>/dev/null + done } # END OF IPUTILS-PING FUNCTIONS @@ -749,35 +1000,25 @@ monitor_reflector_responses_ping() start_pinger() { - local pinger=${1} + local pinger="${1}" log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - # shellcheck disable=SC1083,SC2086,SC2261 case ${pinger_binary} in - tsping) + tsping|fping) pinger=0 - exec {pinger_fds[pinger]}<> <(:) || true - proc_man_start "pinger_${pinger}" ${ping_prefix_string} tsping ${ping_extra_args} --print-timestamps --machine-readable=' ' --sleep-time "0" --target-spacing "${ping_response_interval_ms}" "${reflectors[@]:0:${no_pingers}}" 2> /dev/null >&"${pinger_fds[pinger]}" + printf "START_PINGER\n" >&"${pinger_fds[pinger]}" ;; - fping) - pinger=0 - exec {pinger_fds[pinger]}<> <(:) || true - proc_man_start "pinger_${pinger}" ${ping_prefix_string} fping ${ping_extra_args} --timestamp --loop --period "${reflector_ping_interval_ms}" --interval "${ping_response_interval_ms}" --timeout 10000 "${reflectors[@]:0:${no_pingers}}" 2> /dev/null >&"${pinger_fds[pinger]}" - ;; ping) - exec {pinger_fds[pinger]}<> <(:) || true sleep_until_next_pinger_time_slot "${pinger}" - proc_man_start "pinger_${pinger}" ${ping_prefix_string} ping ${ping_extra_args} -D -i "${reflector_ping_interval_s}" "${reflectors[pinger]}" 2> /dev/null >&"${pinger_fds[pinger]}" + printf "START_PINGER\n" >&"${pinger_fds[pinger]}" ;; *) log_msg "ERROR" "Unknown pinger binary: ${pinger_binary}" exit 1 ;; esac - - proc_man_start "monitor_${pinger}" "monitor_reflector_responses_${pinger_binary}" "${pinger}" } start_pingers() @@ -808,7 +1049,7 @@ sleep_until_next_pinger_time_slot() # this allows pingers to be stopped and started (e.g. during sleep or reflector rotation) # whilst ensuring pings will remain spaced out appropriately to maintain granularity - local pinger=${1} + local pinger="${1}" t_start_us=${EPOCHREALTIME/./} time_to_next_time_slot_us=$(( (reflector_ping_interval_us-(t_start_us-pingers_t_start_us)%reflector_ping_interval_us) + pinger*ping_response_interval_us )) @@ -817,11 +1058,11 @@ sleep_until_next_pinger_time_slot() kill_pinger() { - local pinger=${1} + local pinger="${1}" log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - case ${pinger_binary} in + case "${pinger_binary}" in tsping|fping) pinger=0 ;; @@ -831,16 +1072,12 @@ kill_pinger() ;; esac - proc_man_stop "pinger_${pinger}" - proc_man_stop "monitor_${pinger}" - - # shellcheck disable=SC1083 - exec {pinger_fds[pinger]}<&- + printf "KILL_PINGER\n" >&"${pinger_fds[pinger]}" } kill_pingers() { - case ${pinger_binary} in + case "${pinger_binary}" in tsping|fping) log_msg "DEBUG" "Killing ${pinger_binary} instance." @@ -869,12 +1106,10 @@ replace_pinger_reflector() # and the the bad reflector moved to the back of the queue (last element in ${reflectors[]}) # and finally the indices for ${reflectors} are updated to reflect the new order - local pinger=${1} + local pinger="${1}" log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - lock "${run_path}/replace_pinger_reflector_lock" - if ((no_reflectors > no_pingers)); then log_msg "DEBUG" "replacing reflector: ${reflectors[pinger]} with ${reflectors[no_pingers]}." kill_pinger "${pinger}" @@ -888,13 +1123,20 @@ replace_pinger_reflector() # reset array indices mapfile -t reflectors < <(for i in "${reflectors[@]}"; do printf '%s\n' "${i}"; done) # set up the new pinger with the new reflector and retain pid + case ${pinger_binary} in + + tsping|fping) + printf "SET_REFLECTORS %s\n" "${reflectors[*]:0:${no_pingers}}" >&"${pinger_fds[0]}" + ;; + ping) + printf "SET_REFLECTOR %s\n" "${reflectors[pinger]}" >&"${pinger_fds[pinger]}" + ;; + esac start_pinger "${pinger}" else log_msg "DEBUG" "No additional reflectors specified so just retaining: ${reflectors[pinger]}." reflector_offences[pinger]=0 fi - - unlock "${run_path}/replace_pinger_reflector_lock" } # END OF GENERIC PINGER START AND STOP FUNCTIONS @@ -905,38 +1147,31 @@ kill_maintain_pingers() log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - lock "${run_path}/replace_pinger_reflector_lock" - log_msg "DEBUG" "Terminating maintain_pingers." - kill_pingers + case "${pinger_binary}" in - unlock "${run_path}/replace_pinger_reflector_lock" + tsping|fping) + printf "TERMINATE\n" >&"${pinger_fds[0]}" + ;; + ping) + for((pinger=0; pinger < no_pingers; pinger++)) + do + printf "TERMINATE\n" >&"${pinger_fds[pinger]}" + done + ;; + esac exit } change_state_maintain_pingers() { - local maintain_pingers_next_state=${1:-unset} + local maintain_pingers_next_state="${1:-unset}" log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" - if [[ "${maintain_pingers_next_state}" == "unset" ]]; then - if [[ -f "${run_path}/maintain_pingers_next_state" ]]; then - for ((read_try=1; read_try<11; read_try++)) - do - read -r maintain_pingers_next_state < "${run_path}/maintain_pingers_next_state" - maintain_pingers_next_state=${maintain_pingers_next_state:-unset} - [[ "${maintain_pingers_next_state}" != "unset" ]] && break - done - else - log_msg "ERROR" "Received change signal but ${run_path}/maintain_pingers_next_state does not exist. Exiting now." - kill -INT $$ - fi - fi - - case ${maintain_pingers_next_state} in + case "${maintain_pingers_next_state}" in START|STOP|PAUSED|RUNNING) @@ -944,7 +1179,6 @@ change_state_maintain_pingers() then log_msg "DEBUG" "Changing maintain_pingers state from: ${maintain_pingers_state} to: ${maintain_pingers_next_state}" maintain_pingers_state=${maintain_pingers_next_state} - printf "%s" ${maintain_pingers_state} > ${run_path}/maintain_pingers_state else log_msg "ERROR" "Received request to change maintain_pingers state to existing state." fi @@ -953,7 +1187,7 @@ change_state_maintain_pingers() *) log_msg "ERROR" "Received unrecognized state change request: ${maintain_pingers_next_state}. Exiting now." - kill -INT $$ + kill $$ 2>/dev/null ;; esac } @@ -965,30 +1199,27 @@ maintain_pingers() trap '' INT trap 'kill_maintain_pingers' TERM EXIT - trap 'change_state_maintain_pingers' USR1 - log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" declare -A dl_owd_baselines_us declare -A ul_owd_baselines_us declare -A dl_owd_delta_ewmas_us declare -A ul_owd_delta_ewmas_us + declare -A reflector_last_timestamps_us err_silence=0 reflector_offences_idx=0 pingers_active=0 - pingers_t_start_us=${EPOCHREALTIME/./} - t_last_reflector_replacement_us=${EPOCHREALTIME/./} - t_last_reflector_comparison_us=${EPOCHREALTIME/./} + pingers_t_start_us="${EPOCHREALTIME/./}" + t_last_reflector_replacement_us="${EPOCHREALTIME/./}" + t_last_reflector_comparison_us="${EPOCHREALTIME/./}" for ((reflector=0; reflector < no_reflectors; reflector++)) do - printf '%s' "${pingers_t_start_us}" > "${run_path}/reflector_${reflectors[reflector]//./-}_last_timestamp_us" + reflector_last_timestamps_us["${reflectors[reflector]}"]="${pingers_t_start_us}" done - printf '%s' "${pingers_t_start_us}" > "${run_path}/reflectors_last_timestamp_us" - # For each pinger initialize record of offences for ((pinger=0; pinger < no_pingers; pinger++)) do @@ -999,11 +1230,72 @@ maintain_pingers() done maintain_pingers_state="START" + sleep_duration_s=0 + pinger=0 + + case "${pinger_binary}" in + + tsping) + parse_tsping "parse_tsping" "${reflectors[@]:0:${no_pingers}}" & + printf "SET_PROC_PID proc_pids parse_tsping %s\n" "${!}" >&"${main_fd}" + ;; + fping) + parse_fping "parse_fping" "${reflectors[@]:0:${no_pingers}}" & + printf "SET_PROC_PID proc_pids parse_fping %s\n" "${!}" >&"${main_fd}" + ;; + ping) + for((pinger=0; pinger < no_pingers; pinger++)) + do + parse_ping "parse_ping_${pinger}" "${reflectors[pinger]}" & + printf "SET_PROC_PID proc_pids %s %s\n" "parse_ping_${pinger}" "${!}" >&"${main_fd}" + done + ;; + esac + # Reflector maintenance loop - verifies reflectors have not gone stale and rotates reflectors as necessary while true do - case ${maintain_pingers_state} in + t_start_us="${EPOCHREALTIME/./}" + + while read -r -t 0 -u "${maintain_pingers_fd}" + do + unset command + read -r -u "${maintain_pingers_fd}" -a command + case "${command[0]:-}" in + + CHANGE_STATE) + if [[ "${command[1]:-}" ]] + then + change_state_maintain_pingers "${command[1]}" + # break out of reading any new IPC commands to handle next state + # since next state might be to start or stop pingers + break + fi + ;; + SET_ARRAY_ELEMENT) + if [[ "${command[1]:-}" && "${command[2]:-}" && "${command[3]:-}" ]] + then + declare -A "${command[1]}"+="(["${command[2]}"]="${command[3]}")" + fi + ;; + SET_VAR) + if [[ "${command[1]:-}" && "${command[2]:-}" ]] + then + export -n "${command[1]}=${command[2]}" + fi + ;; + TERMINATE) + log_msg "DEBUG" "Terminating monitor_achieved_rates." + exit + ;; + *) + : + ;; + esac + done + + case "${maintain_pingers_state}" in START) if ((pingers_active==0)) @@ -1027,71 +1319,65 @@ maintain_pingers() ;; RUNNING) - if (( ${EPOCHREALTIME/./}>(t_last_reflector_replacement_us+reflector_replacement_interval_mins*60*1000000))); then - + + if (( ${t_start_us}>(t_last_reflector_replacement_us+reflector_replacement_interval_mins*60*1000000) )) + then + pinger=$((RANDOM%no_pingers)) log_msg "DEBUG" "reflector: ${reflectors[pinger]} randomly selected for replacement." - replace_pinger_reflector $((RANDOM%no_pingers)) + replace_pinger_reflector "${pinger}" t_last_reflector_replacement_us=${EPOCHREALTIME/./} continue fi - if (( ${EPOCHREALTIME/./}>(t_last_reflector_comparison_us+reflector_comparison_interval_mins*60*1000000) )); then + if (( ${t_start_us}>(t_last_reflector_comparison_us+reflector_comparison_interval_mins*60*1000000) )); then t_last_reflector_comparison_us=${EPOCHREALTIME/./} - concurrent_read_integer dl_min_owd_baseline_us "${run_path}/reflector_${reflectors[0]//./-}_dl_owd_baseline_us" 0 || continue - concurrent_read_integer dl_min_owd_delta_ewma_us "${run_path}/reflector_${reflectors[0]//./-}_dl_owd_delta_ewma_us" 0 || continue - concurrent_read_integer ul_min_owd_baseline_us "${run_path}/reflector_${reflectors[0]//./-}_ul_owd_baseline_us" 0 || continue - concurrent_read_integer ul_min_owd_delta_ewma_us "${run_path}/reflector_${reflectors[0]//./-}_ul_owd_delta_ewma_us" 0 || continue - - concurrent_read_integer compensated_dl_delay_thr_us "${run_path}/compensated_dl_delay_thr_us" - concurrent_read_integer compensated_ul_delay_thr_us "${run_path}/compensated_ul_delay_thr_us" + [[ "${dl_owd_baselines_us[${reflectors[0]}]:-}" && "${dl_owd_baselines_us[${reflectors[0]}]:-}" && "${ul_owd_baselines_us[${reflectors[0]}]:-}" && "${ul_owd_baselines_us[${reflectors[0]}]:-}" ]] || continue + + min_sum_owd_baselines_us=$(( dl_owd_baselines_us[${reflectors[0]}] + ul_owd_baselines_us[${reflectors[0]}] )) + min_dl_owd_delta_ewma_us="${dl_owd_delta_ewmas_us[${reflectors[0]}]}" + min_ul_owd_delta_ewma_us="${ul_owd_delta_ewmas_us[${reflectors[0]}]}" for ((pinger=0; pinger < no_pingers; pinger++)) do - concurrent_read_integer "dl_owd_baselines_us[${reflectors[pinger]}]" "${run_path}/reflector_${reflectors[pinger]//./-}_dl_owd_baseline_us" 0 || continue 2 - concurrent_read_integer "dl_owd_delta_ewmas_us[${reflectors[pinger]}]" "${run_path}/reflector_${reflectors[pinger]//./-}_dl_owd_delta_ewma_us" 0 || continue 2 - concurrent_read_integer "ul_owd_baselines_us[${reflectors[pinger]}]" "${run_path}/reflector_${reflectors[pinger]//./-}_ul_owd_baseline_us" 0 || continue 2 - concurrent_read_integer "ul_owd_delta_ewmas_us[${reflectors[pinger]}]" "${run_path}/reflector_${reflectors[pinger]//./-}_ul_owd_delta_ewma_us" 0 || continue 2 - - (( dl_owd_baselines_us[${reflectors[pinger]}] < dl_min_owd_baseline_us )) && dl_min_owd_baseline_us="${dl_owd_baselines_us[${reflectors[pinger]}]}" - (( dl_owd_delta_ewmas_us[${reflectors[pinger]}] < dl_min_owd_delta_ewma_us )) && dl_min_owd_delta_ewma_us="${dl_owd_delta_ewmas_us[${reflectors[pinger]}]}" - (( ul_owd_baselines_us[${reflectors[pinger]}] < ul_min_owd_baseline_us )) && ul_min_owd_baseline_us="${ul_owd_baselines_us[${reflectors[pinger]}]}" - (( ul_owd_delta_ewmas_us[${reflectors[pinger]}] < ul_min_owd_delta_ewma_us )) && ul_min_owd_delta_ewma_us="${ul_owd_delta_ewmas_us[${reflectors[pinger]}]}" + [[ "${dl_owd_baselines_us[${reflectors[pinger]}]:-}" && "${dl_owd_delta_ewmas_us[${reflectors[pinger]}]:-}" && "${ul_owd_baselines_us[${reflectors[pinger]}]:-}" && "${ul_owd_delta_ewmas_us[${reflectors[pinger]}]:-}" ]] || continue 2 + + sum_owd_baselines_us[pinger]=$(( dl_owd_baselines_us[${reflectors[pinger]}] + ul_owd_baselines_us[${reflectors[pinger]}] )) + (( sum_owd_baselines_us[pinger] < min_sum_owd_baselines_us )) && min_sum_owd_baselines_us="${sum_owd_baselines_us[pinger]}" + (( dl_owd_delta_ewmas_us[${reflectors[pinger]}] < min_dl_owd_delta_ewma_us )) && min_dl_owd_delta_ewma_us="${dl_owd_delta_ewmas_us[${reflectors[pinger]}]}" + (( ul_owd_delta_ewmas_us[${reflectors[pinger]}] < min_ul_owd_delta_ewma_us )) && min_ul_owd_delta_ewma_us="${ul_owd_delta_ewmas_us[${reflectors[pinger]}]}" done for ((pinger=0; pinger < no_pingers; pinger++)) do - dl_owd_baseline_delta_us=$(( dl_owd_baselines_us[${reflectors[pinger]}] - dl_min_owd_baseline_us )) - dl_owd_delta_ewma_delta_us=$(( dl_owd_delta_ewmas_us[${reflectors[pinger]}] - dl_min_owd_delta_ewma_us )) - ul_owd_baseline_delta_us=$(( ul_owd_baselines_us[${reflectors[pinger]}] - ul_min_owd_baseline_us )) - ul_owd_delta_ewma_delta_us=$(( ul_owd_delta_ewmas_us[${reflectors[pinger]}] - ul_min_owd_delta_ewma_us )) + sum_owd_baselines_delta_us=$(( sum_owd_baselines_us[pinger] - min_sum_owd_baselines_us )) + dl_owd_delta_ewma_delta_us=$(( dl_owd_delta_ewmas_us[${reflectors[pinger]}] - min_dl_owd_delta_ewma_us )) + ul_owd_delta_ewma_delta_us=$(( ul_owd_delta_ewmas_us[${reflectors[pinger]}] - min_ul_owd_delta_ewma_us )) - if ((output_reflector_stats)); then - printf -v reflector_stats '%s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${reflectors[pinger]}" "${dl_min_owd_baseline_us}" "${dl_owd_baselines_us[${reflectors[pinger]}]}" "${dl_owd_baseline_delta_us}" "${reflector_owd_baseline_delta_thr_us}" "${dl_min_owd_delta_ewma_us}" "${dl_owd_delta_ewmas_us[${reflectors[pinger]}]}" "${dl_owd_delta_ewma_delta_us}" "${reflector_owd_delta_ewma_delta_thr_us}" "${ul_min_owd_baseline_us}" "${ul_owd_baselines_us[${reflectors[pinger]}]}" "${ul_owd_baseline_delta_us}" "${reflector_owd_baseline_delta_thr_us}" "${ul_min_owd_delta_ewma_us}" "${ul_owd_delta_ewmas_us[${reflectors[pinger]}]}" "${ul_owd_delta_ewma_delta_us}" "${reflector_owd_delta_ewma_delta_thr_us}" + if ((output_reflector_stats)) + then + printf -v reflector_stats '%s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${reflectors[pinger]}" "${min_sum_owd_baselines_us}" "${sum_owd_baselines_us[pinger]}" "${sum_owd_baselines_delta_us}" "${reflector_sum_owd_baselines_delta_thr_us}" "${min_dl_owd_delta_ewma_us}" "${dl_owd_delta_ewmas_us[${reflectors[pinger]}]}" "${dl_owd_delta_ewma_delta_us}" "${reflector_owd_delta_ewma_delta_thr_us}" "${min_ul_owd_delta_ewma_us}" "${ul_owd_delta_ewmas_us[${reflectors[pinger]}]}" "${ul_owd_delta_ewma_delta_us}" "${reflector_owd_delta_ewma_delta_thr_us}" log_msg "REFLECTOR" "${reflector_stats}" fi - if (( dl_owd_baseline_delta_us > reflector_owd_baseline_delta_thr_us )); then - log_msg "DEBUG" "Warning: reflector: ${reflectors[pinger]} dl_owd_baseline_us exceeds the minimum by set threshold." + if (( sum_owd_baselines_delta_us > reflector_sum_owd_baselines_delta_thr_us )) + then + log_msg "DEBUG" "Warning: reflector: ${reflectors[pinger]} sum_owd_baselines_us exceeds the minimum by set threshold." replace_pinger_reflector "${pinger}" continue 2 fi - if (( dl_owd_delta_ewma_delta_us > reflector_owd_delta_ewma_delta_thr_us )); then + if (( dl_owd_delta_ewma_delta_us > reflector_owd_delta_ewma_delta_thr_us )) + then log_msg "DEBUG" "Warning: reflector: ${reflectors[pinger]} dl_owd_delta_ewma_us exceeds the minimum by set threshold." replace_pinger_reflector "${pinger}" continue 2 fi - if (( ul_owd_baseline_delta_us > reflector_owd_baseline_delta_thr_us )); then - log_msg "DEBUG" "Warning: reflector: ${reflectors[pinger]} ul_owd_baseline_us exceeds the minimum by set threshold." - replace_pinger_reflector "${pinger}" - continue 2 - fi - - if (( ul_owd_delta_ewma_delta_us > reflector_owd_delta_ewma_delta_thr_us )); then + if (( ul_owd_delta_ewma_delta_us > reflector_owd_delta_ewma_delta_thr_us )) + then log_msg "DEBUG" "Warning: reflector: ${reflectors[pinger]} ul_owd_delta_ewma_us exceeds the minimum by set threshold." replace_pinger_reflector "${pinger}" continue 2 @@ -1104,8 +1390,8 @@ maintain_pingers() for ((pinger=0; pinger < no_pingers; pinger++)) do - reflector_check_time_us=${EPOCHREALTIME/./} - concurrent_read_integer reflector_last_timestamp_us "${run_path}/reflector_${reflectors[pinger]//./-}_last_timestamp_us" + reflector_check_time_us="${EPOCHREALTIME/./}" + reflector_last_timestamp_us="${reflector_last_timestamps_us["${reflectors[pinger]}"]}" # shellcheck disable=SC2178 declare -n reflector_offences="reflector_${pinger}_offences" @@ -1141,26 +1427,22 @@ maintain_pingers() change_maintain_pingers_state ;; esac - - sleep_s "${reflector_health_check_interval_s}" + + sleep_remaining_tick_time "${t_start_us}" "${reflector_health_check_interval_us}" done } set_cake_rate() { - local interface=${1} - local shaper_rate_kbps=${2} - local adjust_shaper_rate=${3} + local interface="${1}" + local shaper_rate_kbps="${2}" + local adjust_shaper_rate="${3}" ((output_cake_changes)) && log_msg "SHAPER" "tc qdisc change root dev ${interface} cake bandwidth ${shaper_rate_kbps}Kbit" if ((adjust_shaper_rate)); then - if ((debug)); then - tc qdisc change root dev "${interface}" cake bandwidth "${shaper_rate_kbps}Kbit" - else - tc qdisc change root dev "${interface}" cake bandwidth "${shaper_rate_kbps}Kbit" 2> /dev/null - fi + tc qdisc change root dev "${interface}" cake bandwidth "${shaper_rate_kbps}Kbit" 2> /dev/null else ((output_cake_changes)) && log_msg "DEBUG" "adjust_shaper_rate set to 0 in config, so skipping the tc qdisc change call" @@ -1169,18 +1451,18 @@ set_cake_rate() set_shaper_rates() { - if (( dl_shaper_rate_kbps != last_dl_shaper_rate_kbps || ul_shaper_rate_kbps != last_ul_shaper_rate_kbps )); then + if (( shaper_rate_kbps[dl] != last_shaper_rate_kbps[dl] || shaper_rate_kbps[ul] != last_shaper_rate_kbps[ul] )); then # fire up tc in each direction if there are rates to change, and if rates change in either direction then update max wire calcs - if (( dl_shaper_rate_kbps != last_dl_shaper_rate_kbps )); then - set_cake_rate "${dl_if}" "${dl_shaper_rate_kbps}" adjust_dl_shaper_rate - printf '%s' "${dl_shaper_rate_kbps}" > "${run_path}/dl_shaper_rate_kbps" - last_dl_shaper_rate_kbps=${dl_shaper_rate_kbps} + if (( shaper_rate_kbps[dl] != last_shaper_rate_kbps[dl] )); then + set_cake_rate "${dl_if}" "${shaper_rate_kbps[dl]}" adjust_dl_shaper_rate + printf "SET_ARRAY_ELEMENT shaper_rate_kbps dl %s\n" "${shaper_rate_kbps[dl]}" >&${monitor_achieved_rates_fd} + last_shaper_rate_kbps[dl]="${shaper_rate_kbps[dl]}" fi - if (( ul_shaper_rate_kbps != last_ul_shaper_rate_kbps )); then - set_cake_rate "${ul_if}" "${ul_shaper_rate_kbps}" adjust_ul_shaper_rate - printf '%s' "${ul_shaper_rate_kbps}" > "${run_path}/ul_shaper_rate_kbps" - last_ul_shaper_rate_kbps=${ul_shaper_rate_kbps} + if (( shaper_rate_kbps[ul] != last_shaper_rate_kbps[ul] )); then + set_cake_rate "${ul_if}" "${shaper_rate_kbps[ul]}" adjust_ul_shaper_rate + printf "SET_ARRAY_ELEMENT shaper_rate_kbps ul %s\n" "${shaper_rate_kbps[ul]}" >&${monitor_achieved_rates_fd} + last_shaper_rate_kbps[ul]="${shaper_rate_kbps[ul]}" fi update_max_wire_packet_compensation @@ -1190,15 +1472,15 @@ set_shaper_rates() set_min_shaper_rates() { log_msg "DEBUG" "Enforcing minimum shaper rates." - dl_shaper_rate_kbps=${min_dl_shaper_rate_kbps} - ul_shaper_rate_kbps=${min_ul_shaper_rate_kbps} + shaper_rate_kbps[dl]=${min_dl_shaper_rate_kbps} + shaper_rate_kbps[ul]=${min_ul_shaper_rate_kbps} set_shaper_rates } get_max_wire_packet_size_bits() { - local interface=${1} - local -n max_wire_packet_size_bits=${2} + local interface="${1}" + local -n max_wire_packet_size_bits="${2}" read -r max_wire_packet_size_bits < "/sys/class/net/${interface}/mtu" [[ $(tc qdisc show dev "${interface}" || true) =~ (atm|noatm)[[:space:]]overhead[[:space:]]([0-9]+) ]] @@ -1213,75 +1495,15 @@ update_max_wire_packet_compensation() # This will serve to increase the delay thr at rates below around 12Mbit/s # compensated OWD delay thresholds in microseconds - compensated_dl_delay_thr_us=$(( dl_delay_thr_us + (1000*dl_max_wire_packet_size_bits)/dl_shaper_rate_kbps )) - compensated_ul_delay_thr_us=$(( ul_delay_thr_us + (1000*ul_max_wire_packet_size_bits)/ul_shaper_rate_kbps )) + compensated_dl_delay_thr_us=$(( dl_delay_thr_us + (1000*dl_max_wire_packet_size_bits)/shaper_rate_kbps[dl] )) + compensated_ul_delay_thr_us=$(( ul_delay_thr_us + (1000*ul_max_wire_packet_size_bits)/shaper_rate_kbps[ul] )) + + printf "SET_VAR compensated_dl_delay_thr_us %s\n" "${compensated_dl_delay_thr_us}" >&"${maintain_pingers_fd}" + printf "SET_VAR compensated_dl_delay_thr_us %s\n" "${compensated_dl_delay_thr_us}" >&"${maintain_pingers_fd}" + + max_wire_packet_rtt_us=$(( (1000*dl_max_wire_packet_size_bits)/shaper_rate_kbps[dl] + (1000*ul_max_wire_packet_size_bits)/shaper_rate_kbps[ul] )) - printf '%s' "${compensated_dl_delay_thr_us}" > "${run_path}/compensated_dl_delay_thr_us" - printf '%s' "${compensated_ul_delay_thr_us}" > "${run_path}/compensated_ul_delay_thr_us" - - # determine and write out ${max_wire_packet_rtt_us} - max_wire_packet_rtt_us=$(( (1000*dl_max_wire_packet_size_bits)/dl_shaper_rate_kbps + (1000*ul_max_wire_packet_size_bits)/ul_shaper_rate_kbps )) - printf '%s' "${max_wire_packet_rtt_us}" > "${run_path}/max_wire_packet_rtt_us" -} - -concurrent_read_integer() -{ - # in the context of a single process that writes to a file and - # a separate process that reads from the file, costly calls to - # the external flock binary can be avoided for the reason that - # the read either reads in a blank value or the last true value - # and so it is possible to just read, test and reread if necessary - - local -n value=${1} - local path=${2} - local exit_on_no_file=${3:-1} - - if ! [[ -f ${path} ]] - then - if ((exit_on_no_file)) - then - log_msg "ERROR" "Non-existent file at: ${path} and exit_on_no_file enabled. Exiting now." - kill -$$ INT - else - log_msg "DEBUG" "Non-existent file at: ${path} but exit_on_no_file disabled. Returning 1." - value=0 - return 1 - fi - fi - - for ((read_try=1; read_try<11; read_try++)) - do - read -r value < "${path}" - value="${value:-unset}" - - # printf '%.0f' is used here to sanitize unsigned integers: - # - it removes any leading zeros whilst preserving the sign; and - # - it returns false if ${value} is not a number - if printf -v sanitized_value '%.0f' "${value}" 2>/dev/null; then - - value=${sanitized_value} - return 0 - - else - if ((debug)); then - read -r caller_output< <(caller) || true - log_msg "DEBUG" "concurrent_read_integer() misfire: ${read_try} of 10, with the following particulars:" - log_msg "DEBUG" "caller=${caller_output}, value=${value} and path=${path}" - fi - sleep_us "${concurrent_read_integer_interval_us}" - continue - fi - done - - if ((debug)); then - read -r caller_output< <(caller) || true - log_msg "ERROR" "If you see this, then please report these messages (ideally with log file)" - log_msg "ERROR" "at the cake-autorate forum of OpenWrt and/or at github.com/lynxthecat/cake-autorate" - log_msg "ERROR" "concurrent_read_integer() 10x misfires, with the following particulars:" - log_msg "ERROR" "caller=${caller_output}, value=${value} and path=${path}" - fi - value=0 - return 1 + printf "SET_VAR max_wire_packet_rtt_us %s\n" "${max_wire_packet_rtt_us}" >&"${maintain_pingers_fd}" } verify_ifs_up() @@ -1300,24 +1522,49 @@ verify_ifs_up() ewma_iteration() { - local value=${1} - local alpha=${2} # alpha must be scaled by factor of 1000000 - local -n ewma=${3} + local value="${1}" + local alpha="${2}" # alpha must be scaled by factor of 1000000 + local -n ewma="${3}" prev_ewma=${ewma} ewma=$(( (alpha*value+(1000000-alpha)*prev_ewma)/1000000 )) } -# redirect stderr to log_msg and exit cake-autorate +change_state_main() +{ + local main_next_state="${1}" + + case ${main_next_state} in + + RUNNING|IDLE|STALL) + + if [[ "${main_state}" != "${main_next_state}" ]] + then + log_msg "DEBUG" "Changing main state from: ${main_state} to: ${main_next_state}" + main_state=${main_next_state} + else + log_msg "ERROR" "Received request to change main state to existing state." + fi + ;; + + *) + + log_msg "ERROR" "Received unrecognized main state change request: ${main_next_state}. Exiting now." + kill $$ 2>/dev/null + ;; + esac +} + intercept_stderr() { - exec 2> >( - while read -r error - do - log_msg "ERROR" "${error}" - kill -INT $$ - done - ) + # send stderr to log_msg and exit cake-autorate + # use with redirection: exec 2> >(intercept_stderr) + + while read -r error + do + log_msg "ERROR" "${error}" + kill $$ 2>/dev/null + done } # Debug command wrapper @@ -1329,9 +1576,9 @@ debug_cmd() # Error messages are output as log_msg ERROR messages # Or set error_silence=1 to output errors as log_msg DEBUG messages - local debug_msg=${1} - local err_silence=${2} - local cmd=${3} + local debug_msg="${1}" + local err_silence="${2}" + local cmd="${3}" log_msg "DEBUG" "Starting: ${FUNCNAME[0]} with PID: ${BASHPID}" @@ -1386,8 +1633,8 @@ log_file_path=/var/log/cake-autorate.log run_path=/var/run/cake-autorate/ # cake-autorate first argument is config file path -if [[ -n ${1:-} ]]; then - config_path=${1} +if [[ -n ${1-} ]]; then + config_path="${1}" else config_path="$PREFIX/cake-autorate_config.primary.sh" fi @@ -1413,10 +1660,7 @@ else exit fi -PROC_STATE_FILE="${run_path}/proc_state" -PROC_STATE_FILE_LOCK="${run_path}/proc_state.lock" - -if [[ -n "${log_file_path_override:-}" ]]; then +if [[ -n "${log_file_path_override-}" ]]; then if [[ ! -d ${log_file_path_override} ]]; then broken_log_file_path_override=${log_file_path_override} log_file_path=/var/log/cake-autorate${instance_id:+.${instance_id}}.log @@ -1430,16 +1674,20 @@ fi rotate_log_file # rotate here to force header prints at top of log file -# Intercept stderr, redirect it to log_msg and exit cake-autorate -intercept_stderr +# save stderr fd, redirect stderr to intercept_stderr +# intercept_stderr sends stderr to log_msg and exits cake-autorate +exec {original_stderr_fd}>&2 2> >(intercept_stderr) + +proc_pids['intercept_stderr']=${!} log_msg "SYSLOG" "Starting cake-autorate with PID: ${BASHPID} and config: ${config_path}" # ${run_path}/ is used to store temporary files # it should not exist on startup so if it does exit, else create the directory if [[ -d "${run_path}" ]]; then - if [[ -f "${run_path}/pid" ]] && [[ -d "/proc/$(<"${run_path}/pid")" ]]; then - log_msg "ERROR" "${run_path} already exists and an instance may be running. Exiting script." + if [[ -f "${run_path}/proc_pids" ]] && running_main_pid=$(awk -F= '/^main=/ {print $2}' ${run_path}/proc_pids) && [[ -d "/proc/${running_main_pid}" ]] + then + log_msg "ERROR" "${run_path} already exists and an instance appears to be running with main process pid ${running_main_pid}. Exiting script." trap - INT TERM EXIT exit else @@ -1451,10 +1699,7 @@ else mkdir -p "${run_path}" fi -# Initialize proc_man -proc_man_initialize - -printf "%s" "${BASHPID}" > "${run_path}/pid" +proc_pids['main']="${BASHPID}" no_reflectors=${#reflectors[@]} @@ -1476,7 +1721,8 @@ if ((log_to_file)); then log_file_max_time_us=$((log_file_max_time_mins*60000000)) log_file_max_size_bytes=$((log_file_max_size_KB*1024)) exec {log_fd}<> <(:) || true - proc_man_start "maintain_log_file" maintain_log_file + maintain_log_file & + proc_pids['maintain_log_file']=${!} fi # test if stdout is a tty (terminal) @@ -1486,7 +1732,7 @@ if ! ((terminal)); then fi # Initialize rx_bytes_path and tx_bytes_path if not set -if [[ -z "${rx_bytes_path:-}" ]]; then +if [[ -z "${rx_bytes_path-}" ]]; then case "${dl_if}" in veth*) rx_bytes_path="/sys/class/net/${dl_if}/statistics/tx_bytes" @@ -1499,7 +1745,7 @@ if [[ -z "${rx_bytes_path:-}" ]]; then ;; esac fi -if [[ -z "${tx_bytes_path:-}" ]]; then +if [[ -z "${tx_bytes_path-}" ]]; then case "${ul_if}" in veth*) tx_bytes_path="/sys/class/net/${ul_if}/statistics/rx_bytes" @@ -1545,10 +1791,11 @@ printf -v shaper_rate_adjust_up_load_low %.0f "${shaper_rate_adjust_up_load_low} printf -v high_load_thr_percent %.0f "${high_load_thr}e2" printf -v reflector_ping_interval_ms %.0f "${reflector_ping_interval_s}e3" printf -v reflector_ping_interval_us %.0f "${reflector_ping_interval_s}e6" +printf -v reflector_health_check_interval_us %.0f "${reflector_health_check_interval_s}e6" printf -v monitor_achieved_rates_interval_us %.0f "${monitor_achieved_rates_interval_ms}e3" printf -v sustained_idle_sleep_thr_us %.0f "${sustained_idle_sleep_thr_s}e6" printf -v reflector_response_deadline_us %.0f "${reflector_response_deadline_s}e6" -printf -v reflector_owd_baseline_delta_thr_us %.0f "${reflector_owd_baseline_delta_thr_ms}e3" +printf -v reflector_sum_owd_baselines_delta_thr_us %.0f "${reflector_sum_owd_baselines_delta_thr_ms}e3" printf -v reflector_owd_delta_ewma_delta_thr_us %.0f "${reflector_owd_delta_ewma_delta_thr_ms}e3" printf -v startup_wait_us %.0f "${startup_wait_s}e6" printf -v global_ping_response_timeout_us %.0f "${global_ping_response_timeout_s}e6" @@ -1571,11 +1818,31 @@ stall_detection_timeout_s=$(( 10#${stall_detection_timeout_s::-6})).${stall_dete concurrent_read_integer_interval_us=$((ping_response_interval_us/4)) -dl_shaper_rate_kbps=${base_dl_shaper_rate_kbps} -ul_shaper_rate_kbps=${base_ul_shaper_rate_kbps} +declare -A bufferbloat_detected +declare -A load_percent +declare -A load_condition +declare -A t_last_bufferbloat_us +declare -A t_last_decay_us +declare -A shaper_rate_kbps +declare -A last_shaper_rate_kbps +declare -A base_shaper_rate_kbps +declare -A min_shaper_rate_kbps +declare -A max_shaper_rate_kbps -last_dl_shaper_rate_kbps=0 -last_ul_shaper_rate_kbps=0 +base_shaper_rate_kbps[dl]="${base_dl_shaper_rate_kbps}" +base_shaper_rate_kbps[ul]="${base_ul_shaper_rate_kbps}" + +min_shaper_rate_kbps[dl]="${min_dl_shaper_rate_kbps}" +min_shaper_rate_kbps[ul]="${min_ul_shaper_rate_kbps}" + +max_shaper_rate_kbps[dl]="${max_dl_shaper_rate_kbps}" +max_shaper_rate_kbps[ul]="${max_ul_shaper_rate_kbps}" + +shaper_rate_kbps[dl]="${base_dl_shaper_rate_kbps}" +shaper_rate_kbps[ul]="${base_ul_shaper_rate_kbps}" + +last_shaper_rate_kbps[dl]=0 +last_shaper_rate_kbps[ul]=0 get_max_wire_packet_size_bits "${dl_if}" dl_max_wire_packet_size_bits get_max_wire_packet_size_bits "${ul_if}" ul_max_wire_packet_size_bits @@ -1584,17 +1851,20 @@ set_shaper_rates update_max_wire_packet_compensation -t_start_us=${EPOCHREALTIME/./} -t_end_us=${EPOCHREALTIME/./} +main_state="RUNNING" -t_prev_ul_rate_set_us=${t_start_us} -t_prev_dl_rate_set_us=${t_start_us} -t_ul_last_bufferbloat_us=${t_start_us} -t_ul_last_decay_us=${t_start_us} -t_dl_last_bufferbloat_us=${t_start_us} -t_dl_last_decay_us=${t_start_us} +t_start_us="${EPOCHREALTIME/./}" +t_end_us="${EPOCHREALTIME/./}" + +t_last_bufferbloat_us[dl]="${t_start_us}" +t_last_bufferbloat_us[ul]="${t_start_us}" +t_last_decay_us[dl]="${t_start_us}" +t_last_decay_us[ul]="${t_start_us}" t_sustained_connection_idle_us=0 +reflectors_last_timestamp_us="${EPOCHREALTIME/./}" +dl_achieved_rate_kbps=0 +ul_achieved_rate_kbps=0 mapfile -t dl_delays < <(for ((i=1; i <= bufferbloat_detection_window; i++)); do echo 0; done) mapfile -t ul_delays < <(for ((i=1; i <= bufferbloat_detection_window; i++)); do echo 0; done) @@ -1625,166 +1895,202 @@ if ((startup_wait_us>0)); then fi # Initiate achieved rate monitor -proc_man_start monitor_achieved_rates monitor_achieved_rates "${rx_bytes_path}" "${tx_bytes_path}" "${monitor_achieved_rates_interval_us}" +monitor_achieved_rates "${rx_bytes_path}" "${tx_bytes_path}" "${monitor_achieved_rates_interval_us}" & +proc_pids[monitor_achieved_rates]="${!}" -printf '%s' "0" > "${run_path}/dl_load_percent" -printf '%s' "0" > "${run_path}/ul_load_percent" +case "${pinger_binary}" in -proc_man_start maintain_pingers maintain_pingers + tsping|fping) + exec {pinger_fds[0]}<> <(:) || true + ;; + ping) + for ((pinger=0; pinger<=no_pingers; pinger++)) + do + exec {pinger_fds[pinger]}<> <(:) || true + done + ;; +esac -generate_log_file_exporter +maintain_pingers & +proc_pids['maintain_pingers']="${!}" + +generate_log_file_scripts log_msg "INFO" "Started cake-autorate with PID: ${BASHPID} and config: ${config_path}" while true do - while read -r -t "${stall_detection_timeout_s}" -u "${ping_fd}" timestamp reflector seq dl_owd_baseline_us dl_owd_us dl_owd_delta_ewma_us dl_owd_delta_us ul_owd_baseline_us ul_owd_us ul_owd_delta_ewma_us ul_owd_delta_us - do - t_start_us=${EPOCHREALTIME/./} - if (( (t_start_us - 10#"${timestamp//[.]}")>500000 )); then - log_msg "DEBUG" "processed response from [${reflector}] that is > 500ms old. Skipping." - continue - fi + unset command + read -r -u "${main_fd}" -a command - # Keep track of number of dl delays across detection window - # .. for download: - (( dl_delays[delays_idx] )) && ((sum_dl_delays--)) - dl_delays[delays_idx]=$(( dl_owd_delta_us > compensated_dl_delay_thr_us ? 1 : 0 )) - ((dl_delays[delays_idx])) && ((sum_dl_delays++)) - # .. for upload - (( ul_delays[delays_idx] )) && ((sum_ul_delays--)) - ul_delays[delays_idx]=$(( ul_owd_delta_us > compensated_ul_delay_thr_us ? 1 : 0 )) - ((ul_delays[delays_idx])) && ((sum_ul_delays++)) - # .. and move index on - (( delays_idx=(delays_idx+1)%bufferbloat_detection_window )) + if [[ "${command-}" ]] + then - dl_bufferbloat_detected=$(( ((sum_dl_delays >= bufferbloat_detection_thr)) ? 1 : 0 )) - ul_bufferbloat_detected=$(( ((sum_ul_delays >= bufferbloat_detection_thr)) ? 1 : 0 )) + case "${command[0]}" in - get_loads + REFLECTOR_RESPONSE) - classify_load "${dl_load_percent}" "${dl_achieved_rate_kbps}" "${dl_bufferbloat_detected}" dl_load_condition - classify_load "${ul_load_percent}" "${ul_achieved_rate_kbps}" "${ul_bufferbloat_detected}" ul_load_condition + read -r timestamp reflector seq dl_owd_baseline_us dl_owd_us dl_owd_delta_ewma_us dl_owd_delta_us ul_owd_baseline_us ul_owd_us ul_owd_delta_ewma_us ul_owd_delta_us <<< "${command[@]:1}" + ;; - dl_load_condition="dl_"${dl_load_condition} - ul_load_condition="ul_"${ul_load_condition} + SET_VAR) + if [[ ${command[1]:-} && ${command[2]:-} ]] + then + export -n "${command[1]}=${command[2]}" + fi + ;; + SET_ARRAY_ELEMENT) + if [[ "${command[1]:-}" && "${command[2]:-}" && "${command[3]:-}" ]] + then + declare -A "${command[1]}"+="(["${command[2]}"]="${command[3]}")" + fi + ;; + SET_PROC_PID) + if [[ "${command[1]:-}" && "${command[2]:-}" && "${command[3]:-}" ]] + then + declare -A "${command[1]}"+="(["${command[2]}"]="${command[3]}")" + fi + > "${run_path}/proc_pids" + for proc_pid in "${!proc_pids[@]}" + do + printf "%s=%s\n" "${proc_pid}" "${proc_pids[${proc_pid}]}" >> "${run_path}/proc_pids" + done + ;; + *) + ;; + esac - get_next_shaper_rate "${min_dl_shaper_rate_kbps}" "${base_dl_shaper_rate_kbps}" "${max_dl_shaper_rate_kbps}" "${dl_achieved_rate_kbps}" "${dl_load_condition}" "${t_start_us}" t_dl_last_bufferbloat_us t_dl_last_decay_us dl_shaper_rate_kbps - get_next_shaper_rate "${min_ul_shaper_rate_kbps}" "${base_ul_shaper_rate_kbps}" "${max_ul_shaper_rate_kbps}" "${ul_achieved_rate_kbps}" "${ul_load_condition}" "${t_start_us}" t_ul_last_bufferbloat_us t_ul_last_decay_us ul_shaper_rate_kbps + fi + case "${main_state}" in - set_shaper_rates + RUNNING) - if (( output_processing_stats )); then - printf -v processing_stats '%s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${dl_achieved_rate_kbps}" "${ul_achieved_rate_kbps}" "${dl_load_percent}" "${ul_load_percent}" "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${compensated_dl_delay_thr_us}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" "${compensated_ul_delay_thr_us}" "${sum_dl_delays}" "${sum_ul_delays}" "${dl_load_condition}" "${ul_load_condition}" "${dl_shaper_rate_kbps}" "${ul_shaper_rate_kbps}" - log_msg "DATA" "${processing_stats}" - fi + if [[ "${command[0]}" == "REFLECTOR_RESPONSE" && "${timestamp-}" && "${reflector-}" && "${seq-}" && "${dl_owd_baseline_us-}" && "${dl_owd_us-}" && "${dl_owd_delta_ewma_us-}" && "${dl_owd_delta_us-}" && "${ul_owd_baseline_us-}" && "${ul_owd_us-}" && "${ul_owd_delta_ewma_us-}" && "${ul_owd_delta_us-}" ]] + then + + t_start_us=${EPOCHREALTIME/./} + + reflectors_last_timestamp_us="${timestamp//[.]}" + + if (( (t_start_us - 10#"${reflectors_last_timestamp_us}")>500000 )); then + log_msg "DEBUG" "processed response from [${reflector}] that is > 500ms old. Skipping." + continue + fi + + # Keep track of number of dl delays across detection window + # .. for download: + (( dl_delays[delays_idx] )) && ((sum_dl_delays--)) + dl_delays[delays_idx]=$(( dl_owd_delta_us > compensated_dl_delay_thr_us ? 1 : 0 )) + ((dl_delays[delays_idx])) && ((sum_dl_delays++)) + # .. for upload + (( ul_delays[delays_idx] )) && ((sum_ul_delays--)) + ul_delays[delays_idx]=$(( ul_owd_delta_us > compensated_ul_delay_thr_us ? 1 : 0 )) + ((ul_delays[delays_idx])) && ((sum_ul_delays++)) + # .. and move index on + (( delays_idx=(delays_idx+1)%bufferbloat_detection_window )) + + bufferbloat_detected[dl]=$(( sum_dl_delays >= bufferbloat_detection_thr ? 1 : 0 )) + bufferbloat_detected[ul]=$(( sum_ul_delays >= bufferbloat_detection_thr ? 1 : 0 )) + + load_percent[dl]=$(( (100*achieved_rate_kbps[dl])/shaper_rate_kbps[dl] )) + load_percent[ul]=$(( (100*achieved_rate_kbps[ul])/shaper_rate_kbps[ul] )) + + classify_load "dl" + classify_load "ul" + + get_next_shaper_rate "dl" + get_next_shaper_rate "ul" + + set_shaper_rates + + if (( output_processing_stats )); then + printf -v processing_stats '%s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s; %s' "${EPOCHREALTIME}" "${achieved_rate_kbps[dl]}" "${achieved_rate_kbps[ul]}" "${load_percent[dl]}" "${load_percent[ul]}" "${timestamp}" "${reflector}" "${seq}" "${dl_owd_baseline_us}" "${dl_owd_us}" "${dl_owd_delta_ewma_us}" "${dl_owd_delta_us}" "${compensated_dl_delay_thr_us}" "${ul_owd_baseline_us}" "${ul_owd_us}" "${ul_owd_delta_ewma_us}" "${ul_owd_delta_us}" "${compensated_ul_delay_thr_us}" "${sum_dl_delays}" "${sum_ul_delays}" "${load_condition[dl]}" "${load_condition[ul]}" "${shaper_rate_kbps[dl]}" "${shaper_rate_kbps[ul]}" + log_msg "DATA" "${processing_stats}" + fi + + # If base rate is sustained, increment sustained base rate timer (and break out of processing loop if enough time passes) + if (( enable_sleep_function )); then + if [[ ${load_condition[dl]} == *idle* && ${load_condition[ul]} == *idle* ]]; then + ((t_sustained_connection_idle_us += (${EPOCHREALTIME/./}-t_end_us) )) + if ((t_sustained_connection_idle_us > sustained_idle_sleep_thr_us)) + then + change_state_main "IDLE" + + log_msg "DEBUG" "Connection idle. Waiting for minimum load." + ((min_shaper_rates_enforcement)) && set_min_shaper_rates + + # update maintain_pingers state + printf "CHANGE_STATE STOP\n" >&"${maintain_pingers_fd}" + + # reset idle timer + t_sustained_connection_idle_us=0 + fi + else + # reset timer + t_sustained_connection_idle_us=0 + fi + fi + elif (( (${EPOCHREALTIME/./} - ${reflectors_last_timestamp_us}) > ${stall_detection_timeout_us} )) + then + + log_msg "DEBUG" "Warning: no reflector response within: ${stall_detection_timeout_s} seconds. Checking loads." + + log_msg "DEBUG" "load check is: (( ${achieved_rate_kbps[dl]} kbps > ${connection_stall_thr_kbps} kbps for download && ${achieved_rate_kbps[ul]} kbps > ${connection_stall_thr_kbps} kbps for upload ))" + + # non-zero load so despite no reflector response within stall interval, the connection not considered to have stalled + # and therefore resume normal operation + if (( achieved_rate_kbps[dl] > connection_stall_thr_kbps && achieved_rate_kbps[ul] > connection_stall_thr_kbps )) + then + + log_msg "DEBUG" "load above connection stall threshold so resuming normal operation." + else + change_state_main "STALL" + + printf "CHANGE_STATE PAUSED\n" >&"${maintain_pingers_fd}" + + t_connection_stall_time_us="${EPOCHREALTIME//.}" + global_ping_response_timeout=0 + fi - # If base rate is sustained, increment sustained base rate timer (and break out of processing loop if enough time passes) - if (( enable_sleep_function )); then - if [[ ${dl_load_condition} == *idle* && ${ul_load_condition} == *idle* ]]; then - ((t_sustained_connection_idle_us += (${EPOCHREALTIME/./}-t_end_us) )) - ((t_sustained_connection_idle_us > sustained_idle_sleep_thr_us)) && break - else - # reset timer - t_sustained_connection_idle_us=0 fi - fi - - t_end_us=${EPOCHREALTIME/./} - - done - - # stall handling procedure - # PIPESTATUS[0] == 142 corresponds with while loop timeout - # i.e. no reflector responses within ${stall_detection_thr} * ${ping_response_interval_us} - if (( PIPESTATUS[0] == 142 )); then - - log_msg "DEBUG" "Warning: no reflector response within: ${stall_detection_timeout_s} seconds. Checking for loads." - - get_loads - - log_msg "DEBUG" "load check is: ((${dl_achieved_rate_kbps} kbps > ${connection_stall_thr_kbps} kbps && ${ul_achieved_rate_kbps} kbps > ${connection_stall_thr_kbps} kbps))" - - # non-zero load so despite no reflector response within stall interval, the connection not considered to have stalled - # and therefore resume normal operation - if (( dl_achieved_rate_kbps > connection_stall_thr_kbps && ul_achieved_rate_kbps > connection_stall_thr_kbps )); then - - log_msg "DEBUG" "load above connection stall threshold so resuming normal operation." - continue - - fi - - log_msg "DEBUG" "Warning: connection stall detection. Waiting for new ping or increased load" - - # save intial global reflector timestamp to check against for any new reflector response - concurrent_read_integer initial_reflectors_last_timestamp_us "${run_path}/reflectors_last_timestamp_us" - - # update maintain_pingers state - printf "PAUSED" > ${run_path}/maintain_pingers_next_state - proc_man_signal maintain_pingers "USR1" - - t_connection_stall_time_us=${EPOCHREALTIME/./} - - global_ping_response_timeout=0 - - # wait until load resumes or ping response received (or global reflector response timeout) - while true - do - t_start_us=${EPOCHREALTIME/./} - concurrent_read_integer new_reflectors_last_timestamp_us "${run_path}/reflectors_last_timestamp_us" - get_loads + t_end_us="${EPOCHREALTIME/./}" - # shellcheck disable=SC2154 - if (( new_reflectors_last_timestamp_us != initial_reflectors_last_timestamp_us || ( dl_achieved_rate_kbps > connection_stall_thr_kbps && ul_achieved_rate_kbps > connection_stall_thr_kbps) )); then + ;; + IDLE) + if (( achieved_rate_kbps[dl] > connection_active_thr_kbps || achieved_rate_kbps[ul] > connection_active_thr_kbps )) + then + log_msg "DEBUG" "dl achieved rate: ${achieved_rate_kbps[dl]} kbps or ul achieved rate: ${achieved_rate_kbps[ul]} kbps exceeded connection active threshold: ${connection_active_thr_kbps} kbps. Resuming normal operation." + change_state_main "RUNNING" + printf "CHANGE_STATE START\n" >&"${maintain_pingers_fd}" + t_sustained_connection_idle_us=0 + # Give some time to enable pingers to get set up + reflectors_last_timestamp_us=$(( "${EPOCHREALTIME/./}" + 2*reflector_ping_interval_us )) + fi + ;; + STALL) + + [[ "${command[0]}" == "REFLECTOR_RESPONSE" && "${timestamp-}" ]] && reflectors_last_timestamp_us=${timestamp//[.]} + + if [[ "${command[0]}" == "REFLECTOR_RESPONSE" ]] || (( achieved_rate_kbps[dl] > connection_stall_thr_kbps && achieved_rate_kbps[ul] > connection_stall_thr_kbps )) + then log_msg "DEBUG" "Connection stall ended. Resuming normal operation." + printf "CHANGE_STATE RUNNING\n" >&"${maintain_pingers_fd}" + change_state_main "RUNNING" - # update maintain_pingers state - printf "RUNNING" > ${run_path}/maintain_pingers_next_state - proc_man_signal maintain_pingers "USR1" - - # continue main loop (i.e. skip idle/global timeout handling below) - continue 2 fi - sleep_remaining_tick_time "${t_start_us}" "${reflector_ping_interval_us}" - - if (( global_ping_response_timeout==0 && t_start_us > (t_connection_stall_time_us + global_ping_response_timeout_us - stall_detection_timeout_us) )); then - log_msg "SYSLOG" "Warning: Configured global ping response timeout: ${global_ping_response_timeout_s} seconds exceeded." - ((min_shaper_rates_enforcement)) && set_min_shaper_rates + if (( global_ping_response_timeout==0 && ${EPOCHREALTIME/./} > (t_connection_stall_time_us + global_ping_response_timeout_us - stall_detection_timeout_us) )) + then global_ping_response_timeout=1 + ((min_shaper_rates_enforcement)) && set_min_shaper_rates + log_msg "SYSLOG" "Warning: Configured global ping response timeout: ${global_ping_response_timeout_s} seconds exceeded." + log_msg "DEBUG" "Restarting pingers." + printf "CHANGE_STATE STOP\n" >&"${maintain_pingers_fd}" + printf "CHANGE_STATE START\n" >&"${maintain_pingers_fd}" fi - done - - else - log_msg "DEBUG" "Connection idle. Waiting for minimum load." - ((min_shaper_rates_enforcement)) && set_min_shaper_rates - fi - - # update maintain_pingers state - printf "STOP" > ${run_path}/maintain_pingers_next_state - proc_man_signal maintain_pingers "USR1" - - # reset idle timer - t_sustained_connection_idle_us=0 - - # wait until load increases again - while true - do - t_start_us=${EPOCHREALTIME/./} - get_loads - - if (( dl_achieved_rate_kbps > connection_active_thr_kbps || ul_achieved_rate_kbps > connection_active_thr_kbps )); then - log_msg "DEBUG" "dl achieved rate: ${dl_achieved_rate_kbps} kbps or ul achieved rate: ${ul_achieved_rate_kbps} kbps exceeded connection active threshold: ${connection_active_thr_kbps} kbps. Resuming normal operation." - break - fi - sleep_remaining_tick_time "${t_start_us}" "${reflector_ping_interval_us}" - done - - # update maintain_pingers state - printf "START" > ${run_path}/maintain_pingers_next_state - proc_man_signal maintain_pingers "USR1" + ;; + esac - t_end_us=${EPOCHREALTIME/./} done diff --git a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_defaults.sh b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_defaults.sh index e6f290d82..06dc9970b 100755 --- a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_defaults.sh +++ b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_defaults.sh @@ -7,8 +7,6 @@ # Author: @Lynx (OpenWrt forum) # Inspiration taken from: @moeller0 (OpenWrt forum) -cake_autorate_version="2.0.0" - # *** OUTPUT AND LOGGING OPTIONS *** output_processing_stats=1 # enable (1) or disable (0) output monitoring lines showing processing stats @@ -44,7 +42,7 @@ ul_if=wan # upload interface # fping - round robin pinging (rtts) # ping - (iputils-ping) individual pinging (rtts) # hping3 - individidual pinging (owds) -pinger_binary=ping +pinger_binary=fping # list of reflectors to use and number of pingers to initiate # pingers will be initiated with reflectors in the order specified in the list @@ -187,9 +185,9 @@ reflector_misbehaving_detection_thr=3 reflector_replacement_interval_mins=60 # how often to replace a random reflector from the present list -reflector_comparison_interval_mins=1 # how often to compare reflectors -reflector_owd_baseline_delta_thr_ms=10 # max increase from min baseline before reflector rotated -reflector_owd_delta_ewma_delta_thr_ms=10 # mac increase from min delta ewma before reflector rotated +reflector_comparison_interval_mins=1 # how often to compare reflectors +reflector_sum_owd_baselines_delta_thr_ms=20 # max increase from min sum owd baselines before reflector rotated +reflector_owd_delta_ewma_delta_thr_ms=10 # max increase from min delta ewma before reflector rotated # stall is detected when the following two conditions are met: # 1) no reflector responses within $stall_detection_thr*$ping_response_interval_us; and diff --git a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_lib.sh b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_lib.sh index 413d191c0..f540e8979 100755 --- a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_lib.sh +++ b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_lib.sh @@ -24,17 +24,22 @@ sleep_s() # - https://github.com/lynxthecat/cake-autorate/issues/174#issuecomment-1460057382 # - https://github.com/lynxthecat/cake-autorate/issues/174#issuecomment-1460074498 + log_msg "DEBUG" "sleep_s" local sleep_duration_s=${1} # (seconds, e.g. 0.5, 1 or 1.5) - read -r -t "${sleep_duration_s}" -u "${__sleep_fd}" || : & - wait "${!}" + log_msg "DEBUG" "sleep_s read ${sleep_duration_s} - ${__sleep_fd}" +# read -r -t "${sleep_duration_s}" -u "${__sleep_fd}" || : + read -r -t "${sleep_duration_s}" -u "${__sleep_fd}" || true + log_msg "DEBUG" "sleep_s read done" } sleep_us() { + log_msg "DEBUG" "WTF ?" local sleep_duration_us=${1} # (microseconds) - + log_msg "DEBUG" "sleep_us" sleep_duration_s=000000${sleep_duration_us} sleep_duration_s=$((10#${sleep_duration_s::-6})).${sleep_duration_s: -6} + log_msg "DEBUG" "go to sleep_s" sleep_s "${sleep_duration_s}" } @@ -53,6 +58,19 @@ sleep_remaining_tick_time() fi } +get_remaining_tick_time() +{ + # updates sleep_duration_s remaining to end of tick duration + + local t_start_us=${1} # (microseconds) + local tick_duration_us=${2} # (microseconds) + + sleep_duration_us=$(( t_start_us + tick_duration_us - ${EPOCHREALTIME/./} )) + ((sleep_duration_us<0)) && sleep_duration_us=0 + sleep_duration_s=000000${sleep_duration_us} + sleep_duration_s=$((10#${sleep_duration_s::-6})).${sleep_duration_s: -6} +} + randomize_array() { local -n array=${1} @@ -85,171 +103,32 @@ unlock() rm -f "${path:?}" } -_proc_man_set_key() +terminate() { - local key=${1} - local value=${2} + # Send regular kill to processes and monitor terminations; + # return as soon as all of the active processes terminate; + # if any processes remain active after one second, kill with fire using kill -9; + # and, finally, call wait on all processes to reap any zombie processes. - lock "${PROC_STATE_FILE_LOCK:?}" - trap 'unlock "${PROC_STATE_FILE_LOCK:?}"' RETURN + local pids=("${@:-}") + + kill "${pids[@]}" 2> /dev/null - local entered=0 - while read -r line; do - if [[ ${line} =~ ^${key}= ]]; then - printf '%s\n' "${key}=${value}" - entered=1 - else - printf '%s\n' "${line}" - fi - done < "${PROC_STATE_FILE:?}" > "${PROC_STATE_FILE:?}.tmp" - if (( entered == 0 )); then - printf '%s\n' "${key}=${value}" >> "${PROC_STATE_FILE:?}.tmp" - fi - mv "${PROC_STATE_FILE:?}.tmp" "${PROC_STATE_FILE:?}" - return 0 + for((i=0; i<10; i++)) + do + for process in "${!pids[@]}" + do + kill -0 "${pids[${process}]}" 2> /dev/null || unset "pids[${process}]" + done + [[ "${pids[*]}" ]] || return + sleep_s 0.1 + done + + kill -9 "${pids[@]}" 2> /dev/null + + wait "${@:-}" } -_proc_man_get_key_value() -{ - local key=${1} - - lock "${PROC_STATE_FILE_LOCK:?}" - trap 'unlock "${PROC_STATE_FILE_LOCK:?}"' RETURN - - while read -r line; do - if [[ ${line} =~ ^${key}= ]]; then - printf '%s\n' "${line#*=}" - return 0 - fi - done < "${PROC_STATE_FILE:?}" - return 1 -} - -proc_man() -{ - local action=${1} - local name=${2} - shift 2 - - if [[ ! -f "${PROC_STATE_FILE:?}" ]]; then - return 1 - fi - - # shellcheck disable=SC2311 - case "${action}" in - "start") - pid=$(_proc_man_get_key_value "${name}") - if (( pid && pid > 0 )) && kill -0 "${pid}" 2> /dev/null; then - return 1; - fi - - "${@}" & - local pid=${!} - _proc_man_set_key "${name}" "${pid}" - ;; - "stop") - local pid - pid=$(_proc_man_get_key_value "${name}") - if ! (( pid && pid > 0 )); then - return 0; - fi - - kill "${pid}" 2> /dev/null || true - - # wait for process to die - killed=0 - for ((i=0; i<10; i++)); - do - if kill -0 "${pid}" 2> /dev/null; then - sleep_us 100000 - else - killed=1 - break - fi - done - - # if process still alive, kill it with fire - if (( killed == 0 )); then - kill -9 "${pid}" 2> /dev/null || true - fi - - _proc_man_set_key "${name}" "-1" "${PROC_STATE_FILE:?}" - ;; - "status") - local pid - pid=$(_proc_man_get_key_value "${name}") - if (( pid && pid > 0 )); then - if kill -0 "${pid}" 2> /dev/null; then - printf '%s\n' "running" - else - printf '%s\n' "dead" - fi - else - printf '%s\n' "stopped" - fi - ;; - "wait") - local pid - pid=$(_proc_man_get_key_value "${name}") - if (( pid && pid > 0 )); then - wait "${pid}" && return 0 - fi - - return 1 - ;; - "signal") - shift 3 - - local pid - pid=$(_proc_man_get_key_value "${name}") - if (( pid && pid > 0 )); then - kill -s "${1}" "${pid}" 2>/dev/null && return 0 - fi - - return 1 - ;; - "initialize") - proc_man_initialize - return $? - ;; - *) - printf '%s\n' "unknown action: ${action}" >&2 - return 1 - ;; - esac - - return 0 -} - -proc_man_initialize() -{ - true > "${PROC_STATE_FILE:?}" -} - -proc_man_start() -{ - proc_man start "${@}" -} - -proc_man_stop() -{ - proc_man stop "${@}" -} - -proc_man_status() -{ - proc_man status "${@}" -} - -proc_man_wait() -{ - proc_man wait "${@}" -} - -proc_man_signal() -{ - proc_man signal "${@}" -} if (( __set_e == 1 )); then set +e diff --git a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh index 5d3195dff..cc01892d0 100755 --- a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh +++ b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh @@ -7,17 +7,21 @@ # Author: @Lynx (OpenWrt forum) # Inspiration taken from: @moeller0 (OpenWrt forum) -INTERFACE=$(basename "$0" | cut -d. -f2) +INTERFACE=$(basename "$1" | cut -d. -f2) cake_autorate_version="2.0.0" # *** OUTPUT AND LOGGING OPTIONS *** -output_processing_stats=$(uci -q get sqm.${INTERFACE}.output_processing_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing processing stats -output_load_stats=$(uci -q get sqm.${INTERFACE}.output_load_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing achieved loads +output_processing_stats=1 +#$(uci -q get sqm.${INTERFACE}.output_processing_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing processing stats +output_load_stats=0 +#$(uci -q get sqm.${INTERFACE}.output_load_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing achieved loads output_reflector_stats=$(uci -q get sqm.${INTERFACE}.output_reflector_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing reflector stats -output_cake_changes=$(uci -q get sqm.${INTERFACE}.output_cake_changes || echo '0') # enable (1) or disable (0) output monitoring lines showing cake bandwidth changes -debug=$(uci -q get sqm.${INTERFACE}.debug || echo '0') # enable (1) or disable (0) out of debug lines +output_cake_changes=0 +#$(uci -q get sqm.${INTERFACE}.output_cake_changes || echo '0') # enable (1) or disable (0) output monitoring lines showing cake bandwidth changes +debug=0 +#$(uci -q get sqm.${INTERFACE}.debug || echo '0') # enable (1) or disable (0) out of debug lines # This can generate a LOT of records so be careful: log_DEBUG_messages_to_syslog=0 # enable (1) or disable (0) logging of all DEBUG records into the system log. @@ -26,7 +30,7 @@ log_DEBUG_messages_to_syslog=0 # enable (1) or disable (0) logging of all DEBUG # every write the cumulative write time and bytes associated with each log line are checked # and if either exceeds the configured values below, the log log file is rotated log_to_file=1 # enable (1) or disable (0) output logging to file (/tmp/cake-autorate.log) -log_file_max_time_mins=10 # maximum time between log file rotations +log_file_max_time_mins=10000 # maximum time between log file rotations log_file_max_size_KB=2000 # maximum KB (i.e. bytes/1024) worth of log lines between log file rotations # log file path defaults to /var/log/ @@ -46,7 +50,7 @@ ul_if=$(uci -q get sqm.${INTERFACE}.interface) # upload interface # fping - round robin pinging (rtts) # ping - (iputils-ping) individual pinging (rtts) # hping3 - individidual pinging (owds) -pinger_binary=ping +pinger_binary=tsping # list of reflectors to use and number of pingers to initiate # pingers will be initiated with reflectors in the order specified in the list @@ -54,16 +58,16 @@ pinger_binary=ping # so e.g. if 6 reflectors are specified and the number of pingers is set to 4, the first 4 reflectors will be used initially # and the remaining 2 reflectors in the list will be used in the event any of the first 4 go bad # a bad reflector will go to the back of the queue on reflector rotation -reflectors=($(uci -q get omr-tracker.defaults.hosts)) -#reflectors=( -#"1.1.1.1" "1.0.0.1" # Cloudflare -#"8.8.8.8" "8.8.4.4" # Google -#"9.9.9.9" "9.9.9.10" "9.9.9.11" # Quad9 -#"94.140.14.15" "94.140.14.140" "94.140.14.141" "94.140.15.15" "94.140.15.16" # AdGuard -#"64.6.65.6" "156.154.70.1" "156.154.70.2" "156.154.70.3" "156.154.70.4" "156.154.70.5" "156.154.71.1" "156.154.71.2" "156.154.71.3" "156.154.71.4" "156.154.71.5" # Neustar -#"208.67.220.2" "208.67.220.123" "208.67.220.220" "208.67.222.2" "208.67.222.123" # OpenDNS -#"185.228.168.9" "185.228.168.10" # CleanBrowsing -#) +#reflectors=$(uci -q get omr-tracker.defaults.hosts) +reflectors=( +"1.1.1.1" "1.0.0.1" # Cloudflare +"8.8.8.8" "8.8.4.4" # Google +"9.9.9.9" "9.9.9.10" "9.9.9.11" # Quad9 +"94.140.14.15" "94.140.14.140" "94.140.14.141" "94.140.15.15" "94.140.15.16" # AdGuard +"64.6.65.6" "156.154.70.1" "156.154.70.2" "156.154.70.3" "156.154.70.4" "156.154.70.5" "156.154.71.1" "156.154.71.2" "156.154.71.3" "156.154.71.4" "156.154.71.5" # Neustar +"208.67.220.2" "208.67.220.123" "208.67.220.220" "208.67.222.2" "208.67.222.123" # OpenDNS +"185.228.168.9" "185.228.168.10" # CleanBrowsing +) randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors on startup @@ -71,14 +75,14 @@ randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors o # to avoid excessive CPU use (proportional with ping interval / number of pingers) # and to avoid abusive network activity (excessive ICMP frequency to one reflector) # The author has found an ICMP rate of 1/(0.2/4) = 20 Hz to give satisfactory performance on 4G -no_pingers=$(uci -q get sqm.${INTERFACE}.no_pingers || echo "6") # number of pingers to maintain -reflector_ping_interval_s=$(uci -q get sqm.${INTERFACE}.reflector_ping_interval_s || echo "0.3") # (seconds, e.g. 0.2s or 2s) +no_pingers=$(uci -q get sqm.${INTERFACE}.no_pingers || echo "4") # number of pingers to maintain +reflector_ping_interval_s=$(uci -q get sqm.${INTERFACE}.reflector_ping_interval_s || echo "1") # (seconds, e.g. 0.2s or 2s) # delay threshold in ms is the extent of OWD increase to classify as a delay # these are automatically adjusted based on maximum on the wire packet size # (adjustment significant at sub 12Mbit/s rates, else negligible) -dl_delay_thr_ms=$(uci -q get sqm.${INTERFACE}.delay_thr_ms || echo "30") # (milliseconds) -ul_delay_thr_ms=$(uci -q get sqm.${INTERFACE}.delay_thr_ms || echo "30") # (milliseconds) +dl_delay_thr_ms=$(uci -q get sqm.${INTERFACE}.delay_thr_ms || echo "100") # (milliseconds) +ul_delay_thr_ms=$(uci -q get sqm.${INTERFACE}.delay_thr_ms || echo "100") # (milliseconds) # Set either of the below to 0 to adjust one direction only # or alternatively set both to 0 to simply use cake-autorate to monitor a connection @@ -97,11 +101,11 @@ max_ul_shaper_rate_kbps=$(uci -q get sqm.${INTERFACE}.max_upload || echo "35000" # pausing all active pingers when connection is not in active use enable_sleep_function=$(uci -q get sqm.${INTERFACE}.enable_sleep_functions || echo "1") # enable (1) or disable (0) sleep functonality connection_active_thr_kbps=$(uci -q get sqm.${INTERFACE}.connection_active_thr_kpbs || echo "1000") # threshold in Kbit/s below which dl/ul is considered idle -sustained_idle_sleep_thr_s=$(uci -q get sqm.${INTERFACE}.sustained_idle_sleep_thr || echo "60.0") # time threshold to put pingers to sleep on sustained dl/ul achieved rate < idle_thr (seconds) +sustained_idle_sleep_thr_s=$(uci -q get sqm.${INTERFACE}.sustained_idle_sleep_thr || echo "150.0") # time threshold to put pingers to sleep on sustained dl/ul achieved rate < idle_thr (seconds) min_shaper_rates_enforcement=$(uci -q get sqm.${INTERFACE}.min_shaper_rates_enforcement || echo "0") # enable (1) or disable (0) dropping down to minimum shaper rates on connection idle or stall -startup_wait_s=$(uci -q get sqm.${INTERFACE}.startup_wait_s || echo "60.0") # number of seconds to wait on startup (e.g. to wait for things to settle on router reboot) +startup_wait_s=$(uci -q get sqm.${INTERFACE}.startup_wait_s || echo "0.0") # number of seconds to wait on startup (e.g. to wait for things to settle on router reboot) # *** ADVANCED CONFIGURATION OPTIONS *** @@ -126,7 +130,8 @@ log_file_export_compress=1 # compress log file exports using gzip and append .gz # Unfortunately, fping does not offer a command line switch to set # the firewall mark. # WARNING: no error checking so use at own risk! -ping_extra_args="- B -I ${INTERFACE}" +#ping_extra_args="-B -I ${INTERFACE}" +ping_extra_args="" # a wrapper for ping binary - used as a prefix for the real command # e.g., when using mwan3, it is recommended to set it like this: @@ -172,13 +177,13 @@ high_load_thr=0.75 # % of currently set bandwidth for detecting high load # the bufferbloat refractory period should be greater than the # average time it would take to replace the bufferbloat # detection window with new samples upon a bufferbloat event -bufferbloat_refractory_period_ms=300 # (milliseconds) +bufferbloat_refractory_period_ms=2000 # (milliseconds) decay_refractory_period_ms=1000 # (milliseconds) # interval for checking reflector health reflector_health_check_interval_s=1.0 # (seconds) # deadline for reflector response not to be classified as an offence against reflector -reflector_response_deadline_s=1.0 # (seconds) +reflector_response_deadline_s=2.0 # (seconds) # reflector misbehaving is detected when $reflector_misbehaving_detection_thr samples # out of the last (reflector misbehaving detection window) samples are offences @@ -190,7 +195,7 @@ reflector_misbehaving_detection_thr=3 reflector_replacement_interval_mins=60 # how often to replace a random reflector from the present list reflector_comparison_interval_mins=1 # how often to compare reflectors -reflector_owd_baseline_delta_thr_ms=10 # max increase from min baseline before reflector rotated +reflector_sum_owd_baseline_delta_thr_ms=30 # max increase from min sum owd baselines before reflector rotated reflector_owd_delta_ewma_delta_thr_ms=10 # mac increase from min delta ewma before reflector rotated # stall is detected when the following two conditions are met: @@ -199,7 +204,7 @@ reflector_owd_delta_ewma_delta_thr_ms=10 # mac increase from min delta ewma be stall_detection_thr=5 connection_stall_thr_kbps=10 -global_ping_response_timeout_s=10.0 # timeout to set shaper rates to min on no ping response whatsoever (seconds) +global_ping_response_timeout_s=100.0 # timeout to set shaper rates to min on no ping response whatsoever (seconds) if_up_check_interval_s=10.0 # time to wait before re-checking if rx/tx bytes files exist (e.g. from boot state or sleep recovery) diff --git a/tsping/Makefile b/tsping/Makefile new file mode 100644 index 000000000..e26a2e642 --- /dev/null +++ b/tsping/Makefile @@ -0,0 +1,38 @@ +include $(TOPDIR)/rules.mk + +PKG_NAME:=tsping +PKG_VERSION:=0.2.3 +PKG_RELEASE:=1 + +PKG_SOURCE_PROTO:=git +PKG_SOURCE_URL:=https://github.com/Lochnair/tsping +PKG_SOURCE_VERSION:=2560d79c95154d2e2c9aa6725135f6fc5cf091d7 + +PKG_MAINTAINER:=Nils Andreas Svee +PKG_LICENSE:=BSD-3-Clause +PKG_LICENSE_FILES:=LICENSE.md + +PKG_INSTALL:=1 +PKG_BUILD_PARALLEL:=1 +PKG_BUILD_DEPENDS:=!USE_GLIBC:argp-standalone + +include $(INCLUDE_DIR)/package.mk +include $(INCLUDE_DIR)/meson.mk + +define Package/tsping + SECTION:=utils + CATEGORY:=Utilities + TITLE:=Utility for sending timestamp pings + URL:=https://github.com/Lochnair/tsping +endef + +define Package/tsping/description + A simple application to send ICMP echo/timestamp requests +endef + +define Package/tsping/install + $(INSTALL_DIR) $(1)/usr/sbin + $(INSTALL_BIN) $(MESON_BUILD_DIR)/tsping $(1)/usr/sbin/ +endef + +$(eval $(call BuildPackage,tsping)) From aaa5499ee91a3dca690faec9b6c9bf728e4b67fd Mon Sep 17 00:00:00 2001 From: "Ycarus (Yannick Chabanois)" Date: Sat, 3 Jun 2023 08:29:17 +0200 Subject: [PATCH 2/4] Fix autorate restart --- mptcp/files/usr/share/omr/post-tracking.d/post-tracking | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mptcp/files/usr/share/omr/post-tracking.d/post-tracking b/mptcp/files/usr/share/omr/post-tracking.d/post-tracking index 5c12d788f..72ceeb373 100755 --- a/mptcp/files/usr/share/omr/post-tracking.d/post-tracking +++ b/mptcp/files/usr/share/omr/post-tracking.d/post-tracking @@ -1752,7 +1752,7 @@ if [ "$(pgrep -f openmptcprouter-vps)" = "" ] && ([ "$(uci -q show openmptcprout sleep 5 fi -if [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.enabled)" = "1" ] && [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.autorate)" = "1" ] && [ -n "$OMR_TRACKER_DEVICE" ] && [ -z $(pgrep -f "autorate.*${OMR_TRACKER_DEVICE}") ]; then +if [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.enabled)" = "1" ] && [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.autorate)" = "1" ] && [ -n "$OMR_TRACKER_DEVICE" ] && [ -z $(pgrep -f "autorate_config.*${OMR_TRACKER_DEVICE}") ]; then /etc/init.d/sqm-autorate restart >/dev/null 2>&1 sleep 5 fi From f14e11ded3e099efddd0e287e3d0358b6fdf33f9 Mon Sep 17 00:00:00 2001 From: "Ycarus (Yannick Chabanois)" Date: Sat, 3 Jun 2023 08:31:06 +0200 Subject: [PATCH 3/4] Fix autorate restart (really) --- mptcp/files/usr/share/omr/post-tracking.d/post-tracking | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mptcp/files/usr/share/omr/post-tracking.d/post-tracking b/mptcp/files/usr/share/omr/post-tracking.d/post-tracking index 72ceeb373..032c7ae3b 100755 --- a/mptcp/files/usr/share/omr/post-tracking.d/post-tracking +++ b/mptcp/files/usr/share/omr/post-tracking.d/post-tracking @@ -1752,7 +1752,7 @@ if [ "$(pgrep -f openmptcprouter-vps)" = "" ] && ([ "$(uci -q show openmptcprout sleep 5 fi -if [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.enabled)" = "1" ] && [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.autorate)" = "1" ] && [ -n "$OMR_TRACKER_DEVICE" ] && [ -z $(pgrep -f "autorate_config.*${OMR_TRACKER_DEVICE}") ]; then +if [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.enabled)" = "1" ] && [ "$(uci -q get sqm.${OMR_TRACKER_INTERFACE}.autorate)" = "1" ] && [ -n "$OMR_TRACKER_DEVICE" ] && [ -z $(pgrep -f "autorate_config.${OMR_TRACKER_INTERFACE}") ]; then /etc/init.d/sqm-autorate restart >/dev/null 2>&1 sleep 5 fi From 193a98bb7f2f2c03402925fe5939b83fad51bd4d Mon Sep 17 00:00:00 2001 From: "Ycarus (Yannick Chabanois)" Date: Sun, 4 Jun 2023 20:54:15 +0200 Subject: [PATCH 4/4] Fix on sqm autorate --- .../sqm-autorate/cake-autorate_template.sh | 26 +++++++++---------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh index cc01892d0..1a9b6105f 100755 --- a/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh +++ b/luci-app-sqm-autorate/root/usr/share/sqm-autorate/cake-autorate_template.sh @@ -13,15 +13,11 @@ cake_autorate_version="2.0.0" # *** OUTPUT AND LOGGING OPTIONS *** -output_processing_stats=1 -#$(uci -q get sqm.${INTERFACE}.output_processing_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing processing stats -output_load_stats=0 -#$(uci -q get sqm.${INTERFACE}.output_load_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing achieved loads +output_processing_stats=$(uci -q get sqm.${INTERFACE}.output_processing_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing processing stats +output_load_stats=$(uci -q get sqm.${INTERFACE}.output_load_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing achieved loads output_reflector_stats=$(uci -q get sqm.${INTERFACE}.output_reflector_stats || echo '0') # enable (1) or disable (0) output monitoring lines showing reflector stats -output_cake_changes=0 -#$(uci -q get sqm.${INTERFACE}.output_cake_changes || echo '0') # enable (1) or disable (0) output monitoring lines showing cake bandwidth changes -debug=0 -#$(uci -q get sqm.${INTERFACE}.debug || echo '0') # enable (1) or disable (0) out of debug lines +output_cake_changes=$(uci -q get sqm.${INTERFACE}.output_cake_changes || echo '0') # enable (1) or disable (0) output monitoring lines showing cake bandwidth changes +debug=$(uci -q get sqm.${INTERFACE}.debug || echo '0') # enable (1) or disable (0) out of debug lines # This can generate a LOT of records so be careful: log_DEBUG_messages_to_syslog=0 # enable (1) or disable (0) logging of all DEBUG records into the system log. @@ -76,13 +72,17 @@ randomize_reflectors=1 # enable (1) or disable (0) randomization of reflectors o # and to avoid abusive network activity (excessive ICMP frequency to one reflector) # The author has found an ICMP rate of 1/(0.2/4) = 20 Hz to give satisfactory performance on 4G no_pingers=$(uci -q get sqm.${INTERFACE}.no_pingers || echo "4") # number of pingers to maintain -reflector_ping_interval_s=$(uci -q get sqm.${INTERFACE}.reflector_ping_interval_s || echo "1") # (seconds, e.g. 0.2s or 2s) +reflector_ping_interval_s=$(uci -q get sqm.${INTERFACE}.reflector_ping_interval_s || echo "0.5") # (seconds, e.g. 0.2s or 2s) # delay threshold in ms is the extent of OWD increase to classify as a delay # these are automatically adjusted based on maximum on the wire packet size -# (adjustment significant at sub 12Mbit/s rates, else negligible) -dl_delay_thr_ms=$(uci -q get sqm.${INTERFACE}.delay_thr_ms || echo "100") # (milliseconds) -ul_delay_thr_ms=$(uci -q get sqm.${INTERFACE}.delay_thr_ms || echo "100") # (milliseconds) +# (adjustment significant at sub 12Mbit/s rates, else negligible) +latency=$(uci -q get sqm.${INTERFACE}.delay_thr_ms) +[ -z "$latency" ] && latency="$(($(ping -B -w 5 -c 5 -I ${ul_if} 1.1.1.1 | cut -d '/' -s -f6 | cut -d '.' -f1 | tr -d '\n' 2>/dev/null)+30))" +[ -z "$latency" ] && latency="100" +logger -t "sqm" "latency $INTERFACE: $latency" +dl_delay_thr_ms="$latency" # (milliseconds) +ul_delay_thr_ms="$latency" # (milliseconds) # Set either of the below to 0 to adjust one direction only # or alternatively set both to 0 to simply use cake-autorate to monitor a connection @@ -131,7 +131,7 @@ log_file_export_compress=1 # compress log file exports using gzip and append .gz # the firewall mark. # WARNING: no error checking so use at own risk! #ping_extra_args="-B -I ${INTERFACE}" -ping_extra_args="" +ping_extra_args="-i ${ul_if}" # a wrapper for ping binary - used as a prefix for the real command # e.g., when using mwan3, it is recommended to set it like this: