CAKE w/ Adaptive Bandwidth [August 2022 to March 2024]

Not sure what you mean, you want me to run

echo "anything" > /tmp/run/cake-autorate/primary/pinger_0_fifo

while running what? strace on something?

How is that supposed to happen though?

That running fping instance might be started from a reflector replacement though and might not be the one that we actually tried to kill?

Yes, open another ssh terminal to the router and run strace there, while issuing the command in another ssh session then you can see whether that process actually consumes your anything message.

strace -y -s 1000 -p 6489 

OK with

root@OpenWrt:~/cake-autorate# strace -y -s 1000 -p 6489
strace: Process 6489 attached
read(0<pipe:[6055]>, 

I've been trying:

root@OpenWrt:~# echo "1" > /tmp/run/cake-autorate/primary/pinger_0_fifo

Previously echoing to the fifo just returned immediately to the command line. Now doing the echo just blocks on the command line until I ctrl-C it. But if I also ctrl-C strace it will now block, so I don't know why it is blocking now but wasn't before.

Also nothing else gets outputted to the strace 6489 window when this echo command is run.

Maybe time now just to try killing fping. Does that get it all unstuck?

OK I killed fping PID 17509.

Immediately the log started printing out DEBUG messages in addition to the LOAD messages.

But, when I run tc I can see that it isn't actually changing the CAKE settings. I tried running speed tests.

An excerpt from the log:

ERROR; 2023-01-26-14:40:56; 1674765656.643585; at the cake-autorate forum of OpenWrt and/or at github.com/lynxthecat/cake-autorate
ERROR; 2023-01-26-14:40:56; 1674765656.652461; concurrent_read_integer() 10x misfires, with the following particulars:
ERROR; 2023-01-26-14:40:56; 1674765656.661659; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_156-154-70-5_dl_owd_baseline_us
LOAD; 2023-01-26-14:40:56; 1674765656.717991; 1674765656.717210; 153; 30; 89054; 10000
LOAD; 2023-01-26-14:40:56; 1674765656.927966; 1674765656.927189; 34; 25; 89054; 10000
LOAD; 2023-01-26-14:40:57; 1674765657.138380; 1674765657.137236; 55; 55; 89054; 10000
LOAD; 2023-01-26-14:40:57; 1674765657.348558; 1674765657.347753; 61; 39; 89054; 10000
LOAD; 2023-01-26-14:40:57; 1674765657.557991; 1674765657.557212; 47; 32; 89054; 10000
DEBUG; 2023-01-26-14:40:57; 1674765657.685117; no ping response from reflector: 156.154.70.5 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:57; 1674765657.694493; reflector=156.154.70.5, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:57; 1674765657.707725; no ping response from reflector: 156.154.71.2 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:57; 1674765657.717124; reflector=156.154.71.2, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:57; 1674765657.729920; no ping response from reflector: 1.0.0.1 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:57; 1674765657.739020; reflector=1.0.0.1, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:57; 1674765657.751754; no ping response from reflector: 156.154.70.4 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:57; 1674765657.761104; reflector=156.154.70.4, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
LOAD; 2023-01-26-14:40:57; 1674765657.769275; 1674765657.768427; 46; 31; 89054; 10000
DEBUG; 2023-01-26-14:40:57; 1674765657.774888; no ping response from reflector: 156.154.71.5 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:57; 1674765657.783957; reflector=156.154.71.5, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:57; 1674765657.796565; no ping response from reflector: 185.228.168.9 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:57; 1674765657.805610; reflector=185.228.168.9, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
LOAD; 2023-01-26-14:40:57; 1674765657.978009; 1674765657.977234; 38; 25; 89054; 10000
LOAD; 2023-01-26-14:40:58; 1674765658.188037; 1674765658.187259; 35; 86; 89054; 10000
LOAD; 2023-01-26-14:40:58; 1674765658.398292; 1674765658.397266; 131; 44; 89054; 10000
LOAD; 2023-01-26-14:40:58; 1674765658.607987; 1674765658.607203; 36; 23; 89054; 10000
LOAD; 2023-01-26-14:40:58; 1674765658.818013; 1674765658.817229; 40; 25; 89054; 10000
DEBUG; 2023-01-26-14:40:58; 1674765658.825389; no ping response from reflector: 156.154.70.5 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:58; 1674765658.834651; reflector=156.154.70.5, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:58; 1674765658.847380; no ping response from reflector: 156.154.71.2 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:58; 1674765658.856588; reflector=156.154.71.2, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:58; 1674765658.869699; no ping response from reflector: 1.0.0.1 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:58; 1674765658.878903; reflector=1.0.0.1, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:58; 1674765658.892025; no ping response from reflector: 156.154.70.4 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:58; 1674765658.901579; reflector=156.154.70.4, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:58; 1674765658.914372; no ping response from reflector: 156.154.71.5 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:58; 1674765658.923483; reflector=156.154.71.5, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:58; 1674765658.936601; no ping response from reflector: 185.228.168.9 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:58; 1674765658.945977; reflector=185.228.168.9, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
LOAD; 2023-01-26-14:40:59; 1674765659.027999; 1674765659.027214; 78; 43; 89054; 10000
LOAD; 2023-01-26-14:40:59; 1674765659.237935; 1674765659.237157; 67; 45; 89054; 10000
LOAD; 2023-01-26-14:40:59; 1674765659.447969; 1674765659.447156; 32; 19; 89054; 10000
LOAD; 2023-01-26-14:40:59; 1674765659.657960; 1674765659.657185; 33; 31; 89054; 10000
LOAD; 2023-01-26-14:40:59; 1674765659.867976; 1674765659.867198; 48; 157; 89054; 10000
DEBUG; 2023-01-26-14:40:59; 1674765659.965177; no ping response from reflector: 156.154.70.5 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:40:59; 1674765659.973905; reflector=156.154.70.5, sum_reflector_offences=3 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:40:59; 1674765659.982471; Warning: reflector: 156.154.70.5 seems to be misbehaving.
DEBUG; 2023-01-26-14:40:59; 1674765659.991982; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.000613; replacing reflector: 156.154.70.5 with 8.8.4.4.
DEBUG; 2023-01-26-14:41:00; 1674765660.009412; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.018673; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.035933; pinger_pids[pinger]=26768 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 156.154.70.5 156.154.71.2 1.0.0.1 156.154.70.4 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:00; 1674765660.046455; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.063654; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26768; result=SUCCESS
LOAD; 2023-01-26-14:41:00; 1674765660.081154; 1674765660.080059; 269; 208; 89054; 10000
DEBUG; 2023-01-26-14:41:00; 1674765660.074986; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.094040; monitor_pids[pinger]=26772 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:00; 1674765660.104045; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.116464; Starting: kill_monitor_reflector_responses_fping with PID: 26772
DEBUG; 2023-01-26-14:41:00; 1674765660.123390; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26772; result=SUCCESS
DEBUG; 2023-01-26-14:41:00; 1674765660.195560; Starting: start_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.211742; Started pinger 0 with PID: 26873
DEBUG; 2023-01-26-14:41:00; 1674765660.230366; pinger_pids[pinger]=26873 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 156.154.71.2 1.0.0.1 156.154.70.4 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:00; 1674765660.242639; Starting: monitor_reflector_responses_fping with PID: 26877
DEBUG; 2023-01-26-14:41:00; 1674765660.250641; monitor_pids[pinger]=26877 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:00; 1674765660.275543; no ping response from reflector: 156.154.71.2 within reflector_response_deadline: 1.0s
LOAD; 2023-01-26-14:41:00; 1674765660.291963; 1674765660.291067; 149; 196; 89054; 10000
DEBUG; 2023-01-26-14:41:00; 1674765660.288394; reflector=156.154.71.2, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:00; 1674765660.300771; Warning: reflector: 156.154.71.2 seems to be misbehaving.
DEBUG; 2023-01-26-14:41:00; 1674765660.310514; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.319902; replacing reflector: 156.154.71.2 with 208.67.222.123.
DEBUG; 2023-01-26-14:41:00; 1674765660.329589; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.340773; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.358752; pinger_pids[pinger]=26873 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 156.154.71.2 1.0.0.1 156.154.70.4 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:00; 1674765660.369928; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.387402; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26873; result=SUCCESS
DEBUG; 2023-01-26-14:41:00; 1674765660.397893; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.414811; monitor_pids[pinger]=26877 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:00; 1674765660.425732; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.438654; Starting: kill_monitor_reflector_responses_fping with PID: 26877
DEBUG; 2023-01-26-14:41:00; 1674765660.443458; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26877; result=SUCCESS
LOAD; 2023-01-26-14:41:00; 1674765660.497927; 1674765660.497142; 79; 24; 89054; 10000
DEBUG; 2023-01-26-14:41:00; 1674765660.515531; Starting: start_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.532033; Started pinger 0 with PID: 26905
DEBUG; 2023-01-26-14:41:00; 1674765660.549868; pinger_pids[pinger]=26905 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 1.0.0.1 156.154.70.4 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:00; 1674765660.563098; Starting: monitor_reflector_responses_fping with PID: 26909
DEBUG; 2023-01-26-14:41:00; 1674765660.571162; monitor_pids[pinger]=26909 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:00; 1674765660.595628; no ping response from reflector: 1.0.0.1 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:00; 1674765660.605234; reflector=1.0.0.1, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:00; 1674765660.614967; Warning: reflector: 1.0.0.1 seems to be misbehaving.
DEBUG; 2023-01-26-14:41:00; 1674765660.624783; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.634494; replacing reflector: 1.0.0.1 with 156.154.70.3.
DEBUG; 2023-01-26-14:41:00; 1674765660.644393; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.655024; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.673614; pinger_pids[pinger]=26905 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 1.0.0.1 156.154.70.4 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:00; 1674765660.684430; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.701170; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26905; result=SUCCESS
LOAD; 2023-01-26-14:41:00; 1674765660.709529; 1674765660.708642; 50; 38; 89054; 10000
DEBUG; 2023-01-26-14:41:00; 1674765660.712251; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.729551; monitor_pids[pinger]=26909 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:00; 1674765660.739772; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.752723; Starting: kill_monitor_reflector_responses_fping with PID: 26909
DEBUG; 2023-01-26-14:41:00; 1674765660.757397; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26909; result=SUCCESS
DEBUG; 2023-01-26-14:41:00; 1674765660.827134; Starting: start_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.843340; Started pinger 0 with PID: 26937
DEBUG; 2023-01-26-14:41:00; 1674765660.862062; pinger_pids[pinger]=26937 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.4 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:00; 1674765660.876023; Starting: monitor_reflector_responses_fping with PID: 26941
DEBUG; 2023-01-26-14:41:00; 1674765660.883830; monitor_pids[pinger]=26941 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:00; 1674765660.907913; no ping response from reflector: 156.154.70.4 within reflector_response_deadline: 1.0s
LOAD; 2023-01-26-14:41:00; 1674765660.922463; 1674765660.921313; 30; 22; 89054; 10000
DEBUG; 2023-01-26-14:41:00; 1674765660.921121; reflector=156.154.70.4, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:00; 1674765660.932623; Warning: reflector: 156.154.70.4 seems to be misbehaving.
DEBUG; 2023-01-26-14:41:00; 1674765660.942323; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.952111; replacing reflector: 156.154.70.4 with 156.154.70.2.
DEBUG; 2023-01-26-14:41:00; 1674765660.962382; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.973208; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:00; 1674765660.991669; pinger_pids[pinger]=26937 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.4 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:01; 1674765661.002240; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.019234; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26937; result=SUCCESS
DEBUG; 2023-01-26-14:41:01; 1674765661.029216; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.046345; monitor_pids[pinger]=26941 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:01; 1674765661.056792; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.070222; Starting: kill_monitor_reflector_responses_fping with PID: 26941
DEBUG; 2023-01-26-14:41:01; 1674765661.074762; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26941; result=SUCCESS
LOAD; 2023-01-26-14:41:01; 1674765661.127880; 1674765661.127101; 40; 24; 89054; 10000
DEBUG; 2023-01-26-14:41:01; 1674765661.146137; Starting: start_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.163101; Started pinger 0 with PID: 26969
DEBUG; 2023-01-26-14:41:01; 1674765661.181323; pinger_pids[pinger]=26969 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.2 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:01; 1674765661.194404; Starting: monitor_reflector_responses_fping with PID: 26973
DEBUG; 2023-01-26-14:41:01; 1674765661.202247; monitor_pids[pinger]=26973 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:01; 1674765661.227165; no ping response from reflector: 156.154.71.5 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:01; 1674765661.236771; reflector=156.154.71.5, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:01; 1674765661.246726; Warning: reflector: 156.154.71.5 seems to be misbehaving.
DEBUG; 2023-01-26-14:41:01; 1674765661.256614; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.267759; replacing reflector: 156.154.71.5 with 208.67.220.123.
DEBUG; 2023-01-26-14:41:01; 1674765661.277577; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.288068; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.306567; pinger_pids[pinger]=26969 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.2 156.154.71.5 185.228.168.9
DEBUG; 2023-01-26-14:41:01; 1674765661.317069; Starting: debug_cmd with PID: 25275
LOAD; 2023-01-26-14:41:01; 1674765661.339657; 1674765661.338798; 59; 34; 89054; 10000
DEBUG; 2023-01-26-14:41:01; 1674765661.334631; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26969; result=SUCCESS
DEBUG; 2023-01-26-14:41:01; 1674765661.345248; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.362721; monitor_pids[pinger]=26973 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:01; 1674765661.372992; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.385887; Starting: kill_monitor_reflector_responses_fping with PID: 26973
DEBUG; 2023-01-26-14:41:01; 1674765661.390952; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 26973; result=SUCCESS
DEBUG; 2023-01-26-14:41:01; 1674765661.463062; Starting: start_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.479548; Started pinger 0 with PID: 27001
DEBUG; 2023-01-26-14:41:01; 1674765661.497541; pinger_pids[pinger]=27001 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.2 208.67.220.123 185.228.168.9
DEBUG; 2023-01-26-14:41:01; 1674765661.510979; Starting: monitor_reflector_responses_fping with PID: 27005
DEBUG; 2023-01-26-14:41:01; 1674765661.518830; monitor_pids[pinger]=27005 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
LOAD; 2023-01-26-14:41:01; 1674765661.550708; 1674765661.549535; 42; 86; 89054; 10000
DEBUG; 2023-01-26-14:41:01; 1674765661.544365; no ping response from reflector: 185.228.168.9 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:01; 1674765661.556561; reflector=185.228.168.9, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:01; 1674765661.566952; Warning: reflector: 185.228.168.9 seems to be misbehaving.
DEBUG; 2023-01-26-14:41:01; 1674765661.577320; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.587651; replacing reflector: 185.228.168.9 with 1.1.1.1.
DEBUG; 2023-01-26-14:41:01; 1674765661.598684; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.609850; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.628712; pinger_pids[pinger]=27001 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.2 208.67.220.123 185.228.168.9
DEBUG; 2023-01-26-14:41:01; 1674765661.639294; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.657240; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 27001; result=SUCCESS
DEBUG; 2023-01-26-14:41:01; 1674765661.667417; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.684574; monitor_pids[pinger]=27005 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:01; 1674765661.695538; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.708863; Starting: kill_monitor_reflector_responses_fping with PID: 27005
DEBUG; 2023-01-26-14:41:01; 1674765661.713724; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 27005; result=SUCCESS
LOAD; 2023-01-26-14:41:01; 1674765661.758028; 1674765661.757251; 129; 31; 89054; 10000
DEBUG; 2023-01-26-14:41:01; 1674765661.785285; Starting: start_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:01; 1674765661.802099; Started pinger 0 with PID: 27033
DEBUG; 2023-01-26-14:41:01; 1674765661.820423; pinger_pids[pinger]=27033 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.2 208.67.220.123 1.1.1.1
DEBUG; 2023-01-26-14:41:01; 1674765661.833704; Starting: monitor_reflector_responses_fping with PID: 27037
DEBUG; 2023-01-26-14:41:01; 1674765661.841506; monitor_pids[pinger]=27037 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
LOAD; 2023-01-26-14:41:01; 1674765661.968294; 1674765661.967509; 49; 34; 89054; 10000
LOAD; 2023-01-26-14:41:02; 1674765662.177864; 1674765662.177087; 53; 42; 89054; 10000
LOAD; 2023-01-26-14:41:02; 1674765662.388179; 1674765662.387392; 59; 43; 89054; 10000
LOAD; 2023-01-26-14:41:02; 1674765662.597954; 1674765662.597169; 33; 19; 89054; 10000
LOAD; 2023-01-26-14:41:02; 1674765662.807962; 1674765662.807180; 32; 22; 89054; 10000
DEBUG; 2023-01-26-14:41:02; 1674765662.875175; no ping response from reflector: 8.8.4.4 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:02; 1674765662.883911; reflector=8.8.4.4, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:02; 1674765662.895998; no ping response from reflector: 208.67.222.123 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:02; 1674765662.905358; reflector=208.67.222.123, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:02; 1674765662.917352; no ping response from reflector: 156.154.70.3 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:02; 1674765662.926168; reflector=156.154.70.3, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:02; 1674765662.938143; no ping response from reflector: 156.154.70.2 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:02; 1674765662.946693; reflector=156.154.70.2, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:02; 1674765662.959154; no ping response from reflector: 208.67.220.123 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:02; 1674765662.967823; reflector=208.67.220.123, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:02; 1674765662.980011; no ping response from reflector: 1.1.1.1 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:02; 1674765662.988403; reflector=1.1.1.1, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3
LOAD; 2023-01-26-14:41:03; 1674765663.018679; 1674765663.017876; 44; 42; 89054; 10000
LOAD; 2023-01-26-14:41:03; 1674765663.227965; 1674765663.227183; 68; 56; 89054; 10000
LOAD; 2023-01-26-14:41:03; 1674765663.437972; 1674765663.437198; 44; 28; 89054; 10000
LOAD; 2023-01-26-14:41:03; 1674765663.648211; 1674765663.647429; 23; 32; 89054; 10000
LOAD; 2023-01-26-14:41:03; 1674765663.857947; 1674765663.857171; 43; 28; 89054; 10000
DEBUG; 2023-01-26-14:41:04; 1674765664.005131; no ping response from reflector: 8.8.4.4 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:04; 1674765664.013741; reflector=8.8.4.4, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:04; 1674765664.025588; no ping response from reflector: 208.67.222.123 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:04; 1674765664.034349; reflector=208.67.222.123, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:04; 1674765664.046205; no ping response from reflector: 156.154.70.3 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:04; 1674765664.054872; reflector=156.154.70.3, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
LOAD; 2023-01-26-14:41:04; 1674765664.069604; 1674765664.068659; 31; 25; 89054; 10000
DEBUG; 2023-01-26-14:41:04; 1674765664.066971; no ping response from reflector: 156.154.70.2 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:04; 1674765664.076286; reflector=156.154.70.2, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:04; 1674765664.088862; no ping response from reflector: 208.67.220.123 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:04; 1674765664.097370; reflector=208.67.220.123, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:04; 1674765664.109359; no ping response from reflector: 1.1.1.1 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:04; 1674765664.118185; reflector=1.1.1.1, sum_reflector_offences=2 and reflector_misbehaving_detection_thr=3
LOAD; 2023-01-26-14:41:04; 1674765664.278756; 1674765664.277967; 72; 35; 89054; 10000
LOAD; 2023-01-26-14:41:04; 1674765664.488308; 1674765664.487177; 40; 30; 89054; 10000
LOAD; 2023-01-26-14:41:04; 1674765664.698020; 1674765664.697236; 57; 50; 89054; 10000
LOAD; 2023-01-26-14:41:04; 1674765664.908510; 1674765664.907725; 49; 100; 89054; 10000
LOAD; 2023-01-26-14:41:05; 1674765665.118037; 1674765665.117252; 163; 41; 89054; 10000
DEBUG; 2023-01-26-14:41:05; 1674765665.135096; no ping response from reflector: 8.8.4.4 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:05; 1674765665.144023; reflector=8.8.4.4, sum_reflector_offences=3 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:05; 1674765665.153513; Warning: reflector: 8.8.4.4 seems to be misbehaving.
DEBUG; 2023-01-26-14:41:05; 1674765665.162954; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.173241; replacing reflector: 8.8.4.4 with 94.140.14.141.
DEBUG; 2023-01-26-14:41:05; 1674765665.183922; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.193609; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.211192; pinger_pids[pinger]=27033 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 8.8.4.4 208.67.222.123 156.154.70.3 156.154.70.2 208.67.220.123 1.1.1.1
DEBUG; 2023-01-26-14:41:05; 1674765665.222202; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.239377; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 27033; result=SUCCESS
DEBUG; 2023-01-26-14:41:05; 1674765665.250055; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.267650; monitor_pids[pinger]=27037 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:05; 1674765665.278539; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.291670; Starting: kill_monitor_reflector_responses_fping with PID: 27037
DEBUG; 2023-01-26-14:41:05; 1674765665.296363; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 27037; result=SUCCESS
LOAD; 2023-01-26-14:41:05; 1674765665.330916; 1674765665.329551; 150; 223; 89054; 10000
DEBUG; 2023-01-26-14:41:05; 1674765665.374726; Starting: start_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.391520; Started pinger 0 with PID: 27089
DEBUG; 2023-01-26-14:41:05; 1674765665.409542; pinger_pids[pinger]=27089 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 94.140.14.141 208.67.222.123 156.154.70.3 156.154.70.2 208.67.220.123 1.1.1.1
DEBUG; 2023-01-26-14:41:05; 1674765665.421996; Starting: monitor_reflector_responses_fping with PID: 27093
DEBUG; 2023-01-26-14:41:05; 1674765665.429851; monitor_pids[pinger]=27093 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:05; 1674765665.453891; no ping response from reflector: 208.67.222.123 within reflector_response_deadline: 1.0s
DEBUG; 2023-01-26-14:41:05; 1674765665.463775; reflector=208.67.222.123, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
DEBUG; 2023-01-26-14:41:05; 1674765665.473598; Warning: reflector: 208.67.222.123 seems to be misbehaving.
DEBUG; 2023-01-26-14:41:05; 1674765665.483546; Starting: replace_pinger_reflector with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.493808; replacing reflector: 208.67.222.123 with 185.228.168.10.
DEBUG; 2023-01-26-14:41:05; 1674765665.503407; Starting: kill_pinger with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.513704; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.533560; pinger_pids[pinger]=27089 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 94.140.14.141 208.67.222.123 156.154.70.3 156.154.70.2 208.67.220.123 1.1.1.1
LOAD; 2023-01-26-14:41:05; 1674765665.540753; 1674765665.539512; 37; 25; 89054; 10000
DEBUG; 2023-01-26-14:41:05; 1674765665.545674; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.563148; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 27089; result=SUCCESS
DEBUG; 2023-01-26-14:41:05; 1674765665.573655; Starting: kill_and_wait_by_pid_name with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.591216; monitor_pids[pinger]=27093 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh
DEBUG; 2023-01-26-14:41:05; 1674765665.601686; Starting: debug_cmd with PID: 25275
DEBUG; 2023-01-26-14:41:05; 1674765665.614515; Starting: kill_monitor_reflector_responses_fping with PID: 27093
DEBUG; 2023-01-26-14:41:05; 1674765665.619104; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 27093; result=SUCCESS

Right after I did the kill:

LOAD; 2023-01-26-14:38:50; 1674765530.287981; 1674765530.287198; 39; 21; 89054; 10000                                                                                                                                         
LOAD; 2023-01-26-14:38:50; 1674765530.497915; 1674765530.497138; 27; 15; 89054; 10000                                                                                                                                          
LOAD; 2023-01-26-14:38:50; 1674765530.708294; 1674765530.707508; 22; 12; 89054; 10000                                                                                                                                              
LOAD; 2023-01-26-14:38:50; 1674765530.917921; 1674765530.917135; 64; 41; 89054; 10000                                                                                                                                            
LOAD; 2023-01-26-14:38:51; 1674765531.127907; 1674765531.127124; 46; 47; 89054; 10000                                                                                                                                
LOAD; 2023-01-26-14:38:51; 1674765531.338311; 1674765531.337532; 31; 96; 89054; 10000                                                                                                                                     
LOAD; 2023-01-26-14:38:51; 1674765531.547978; 1674765531.547198; 148; 77; 89054; 10000                                                                                                                                             
LOAD; 2023-01-26-14:38:51; 1674765531.758551; 1674765531.757768; 20; 23; 89054; 10000                                                                                                                                              
LOAD; 2023-01-26-14:38:51; 1674765531.968124; 1674765531.967336; 87; 196; 89054; 10000                                                                                                                                             
LOAD; 2023-01-26-14:38:52; 1674765532.177931; 1674765532.177145; 36; 18; 89054; 10000                                                                                                                                  
LOAD; 2023-01-26-14:38:52; 1674765532.387931; 1674765532.387152; 39; 24; 89054; 10000                                                                                                                                         
DEBUG; 2023-01-26-14:38:52; 1674711478.200489; pinger_pids[pinger]=17509 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 9.9.9.10 8.8.8.8 9.9.9.9 208.67.220.2 208.67.220.220 94.140.14.15        
DEBUG; 2023-01-26-14:38:52; 1674765532.455951; Starting: monitor_reflector_responses_fping with PID: 21795                                                                           
DEBUG; 2023-01-26-14:38:52; 1674765532.463787; monitor_pids[pinger]=21795 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh                                         
DEBUG; 2023-01-26-14:38:52; 1674765532.487271; no ping response from reflector: 208.67.220.220 within reflector_response_deadline: 1.0s                                                                                          
DEBUG; 2023-01-26-14:38:52; 1674765532.496759; reflector=208.67.220.220, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3                                                                                
DEBUG; 2023-01-26-14:38:52; 1674765532.506260; Warning: reflector: 208.67.220.220 seems to be misbehaving.                                                                           
DEBUG; 2023-01-26-14:38:52; 1674765532.516532; Starting: replace_pinger_reflector with PID: 25275                                                                                                                           
DEBUG; 2023-01-26-14:38:52; 1674765532.526222; replacing reflector: 208.67.220.220 with 208.67.222.2.                                                                                                                                
DEBUG; 2023-01-26-14:38:52; 1674765532.535742; Starting: kill_pinger with PID: 25275                                                                                                                                               
DEBUG; 2023-01-26-14:38:52; 1674765532.545990; Starting: kill_and_wait_by_pid_name with PID: 25275                                                                                   
DEBUG; 2023-01-26-14:38:52; 1674765532.555683; expected pinger_pids[pinger] process: 17509 does not exist - nothing to kill.                                                                                                  
DEBUG; 2023-01-26-14:38:52; 1674765532.565999; Starting: kill_and_wait_by_pid_name with PID: 25275                                                                                                                                 
DEBUG; 2023-01-26-14:38:52; 1674765532.583418; monitor_pids[pinger]=21795 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh                                         
LOAD; 2023-01-26-14:38:52; 1674765532.601245; 1674765532.600338; 8; 7; 89054; 10000                                                                                                                                   
DEBUG; 2023-01-26-14:38:52; 1674765532.596412; Starting: debug_cmd with PID: 25275                                                                                                                                               
DEBUG; 2023-01-26-14:38:52; 1674765532.610000; Starting: kill_monitor_reflector_responses_fping with PID: 21795                                                                                                             
DEBUG; 2023-01-26-14:38:52; 1674765532.614915; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 21795; result=SUCCESS                      
DEBUG; 2023-01-26-14:38:52; 1674765532.687841; Starting: start_pinger with PID: 25275                                                                                                                                       
DEBUG; 2023-01-26-14:38:52; 1674765532.704238; Started pinger 0 with PID: 21818                                                                                                                                                      
DEBUG; 2023-01-26-14:38:52; 1674765532.722546; pinger_pids[pinger]=21818 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 9.9.9.10 8.8.8.8 9.9.9.9 208.67.220.2 208.67.222.2 94.140.14.15              
DEBUG; 2023-01-26-14:38:52; 1674765532.735869; Starting: monitor_reflector_responses_fping with PID: 21822                                                                                     
DEBUG; 2023-01-26-14:38:52; 1674765532.744165; monitor_pids[pinger]=21822 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh                                         
DEBUG; 2023-01-26-14:38:52; 1674765532.768104; no ping response from reflector: 94.140.14.15 within reflector_response_deadline: 1.0s                                                                                              
DEBUG; 2023-01-26-14:38:52; 1674765532.777764; reflector=94.140.14.15, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3                                            
DEBUG; 2023-01-26-14:38:52; 1674765532.787411; Warning: reflector: 94.140.14.15 seems to be misbehaving.                                                                                                               
DEBUG; 2023-01-26-14:38:52; 1674765532.797454; Starting: replace_pinger_reflector with PID: 25275                                                                                                                                  
LOAD; 2023-01-26-14:38:52; 1674765532.811838; 1674765532.810729; 179; 63; 89054; 10000                                                                                                                                      
DEBUG; 2023-01-26-14:38:52; 1674765532.811227; replacing reflector: 94.140.14.15 with 94.140.15.15.                                                                                                                  
DEBUG; 2023-01-26-14:38:52; 1674765532.823658; Starting: kill_pinger with PID: 25275                                                                                                                                        
DEBUG; 2023-01-26-14:38:52; 1674765532.833914; Starting: kill_and_wait_by_pid_name with PID: 25275                                                                                                                                 
DEBUG; 2023-01-26-14:38:52; 1674765532.852039; pinger_pids[pinger]=21818 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 9.9.9.10 8.8.8.8 9.9.9.9 208.67.220.2 208.67.222.2 94.140.14.15              
DEBUG; 2023-01-26-14:38:52; 1674765532.862419; Starting: debug_cmd with PID: 25275                                                                                                             
DEBUG; 2023-01-26-14:38:52; 1674765532.879262; debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 21818; result=SUCCESS                                
DEBUG; 2023-01-26-14:38:52; 1674765532.889878; Starting: kill_and_wait_by_pid_name with PID: 25275                                                                                                                            
DEBUG; 2023-01-26-14:38:52; 1674765532.906836; monitor_pids[pinger]=21822 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh                                       
DEBUG; 2023-01-26-14:38:52; 1674765532.917323; Starting: debug_cmd with PID: 25275                                                                                                                                                 
DEBUG; 2023-01-26-14:38:52; 1674765532.930873; Starting: kill_monitor_reflector_responses_fping with PID: 21822                                                                                                       

More around those ERROR lines

DEBUG; 2023-01-26-14:38:54; 1674765534.226732; Starting: kill_monitor_reflector_responses_fping with PID: 21854                                                                                                                                   
DEBUG; 2023-01-26-14:38:54; 1674765534.231661; debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=660 /root/cake-autorate/cake-autorate.sh; command=kill 21854; result=SUCCESS                              
LOAD; 2023-01-26-14:38:54; 1674765534.277969; 1674765534.277175; 103; 108; 89054; 10000                                                                                                                                                           
DEBUG; 2023-01-26-14:38:54; 1674765534.306037; Starting: start_pinger with PID: 25275                                                                                                                                         
DEBUG; 2023-01-26-14:38:54; 1674765534.322462; Started pinger 0 with PID: 21880                                                                                                                                                
DEBUG; 2023-01-26-14:38:54; 1674765534.341489; pinger_pids[pinger]=21880 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 9.9.9.10 8.8.8.8 94.140.14.140 208.67.220.2 208.67.222.2 94.140.15.15        
DEBUG; 2023-01-26-14:38:54; 1674765534.353809; Starting: monitor_reflector_responses_fping with PID: 21884                                                                                                                       
DEBUG; 2023-01-26-14:38:54; 1674765534.361700; monitor_pids[pinger]=21884 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.primary.sh                                
LOAD; 2023-01-26-14:38:54; 1674765534.488343; 1674765534.487547; 49; 85; 89054; 10000                                                                                                                                     
LOAD; 2023-01-26-14:38:54; 1674765534.698003; 1674765534.697202; 38; 24; 89054; 10000                                                                                                                                              
LOAD; 2023-01-26-14:38:54; 1674765534.907979; 1674765534.907195; 104; 93; 89054; 10000                                                                                                                                             
LOAD; 2023-01-26-14:38:55; 1674765535.118045; 1674765535.117260; 116; 200; 89054; 10000                                                                                                                                            
LOAD; 2023-01-26-14:38:55; 1674765535.328390; 1674765535.327608; 100; 34; 89054; 10000                                                                                                                                 
DEBUG; 2023-01-26-14:38:55; 1674765535.419712; concurrent_read_integer() misfire: 1 of 10, with the following particulars:                                                                                                    
DEBUG; 2023-01-26-14:38:55; 1674765535.429621; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                            
DEBUG; 2023-01-26-14:38:55; 1674765535.466602; concurrent_read_integer() misfire: 2 of 10, with the following particulars:                                                           
DEBUG; 2023-01-26-14:38:55; 1674765535.475918; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                           
DEBUG; 2023-01-26-14:38:55; 1674765535.506287; concurrent_read_integer() misfire: 3 of 10, with the following particulars:                                                                                                       
DEBUG; 2023-01-26-14:38:55; 1674765535.515698; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                        
LOAD; 2023-01-26-14:38:55; 1674765535.537736; 1674765535.536964; 43; 30; 89054; 10000                                                                                                
DEBUG; 2023-01-26-14:38:55; 1674765535.547388; concurrent_read_integer() misfire: 4 of 10, with the following particulars:                                                                                                  
DEBUG; 2023-01-26-14:38:55; 1674765535.557353; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                                  
DEBUG; 2023-01-26-14:38:55; 1674765535.586932; concurrent_read_integer() misfire: 5 of 10, with the following particulars:                                                                                                         
DEBUG; 2023-01-26-14:38:55; 1674765535.596162; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us  
DEBUG; 2023-01-26-14:38:55; 1674765535.626672; concurrent_read_integer() misfire: 6 of 10, with the following particulars:                                                                                                    
DEBUG; 2023-01-26-14:38:55; 1674765535.635992; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                                
DEBUG; 2023-01-26-14:38:55; 1674765535.666264; concurrent_read_integer() misfire: 7 of 10, with the following particulars:                                                                                                    
DEBUG; 2023-01-26-14:38:55; 1674765535.675676; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                   
DEBUG; 2023-01-26-14:38:55; 1674765535.706294; concurrent_read_integer() misfire: 8 of 10, with the following particulars:                                                                                                       
DEBUG; 2023-01-26-14:38:55; 1674765535.715585; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                         
LOAD; 2023-01-26-14:38:55; 1674765535.751489; 1674765535.749773; 40; 24; 89054; 10000                                                                                                                                
DEBUG; 2023-01-26-14:38:55; 1674765535.748219; concurrent_read_integer() misfire: 9 of 10, with the following particulars:                                                                                                  
DEBUG; 2023-01-26-14:38:55; 1674765535.759866; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                                  
DEBUG; 2023-01-26-14:38:55; 1674765535.796735; concurrent_read_integer() misfire: 10 of 10, with the following particulars:                                                                                                        
DEBUG; 2023-01-26-14:38:55; 1674765535.805898; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us            
ERROR; 2023-01-26-14:38:55; 1674765535.834810; If you see this, then please report these messages (ideally with log file)                                                                                                     
ERROR; 2023-01-26-14:38:55; 1674765535.843615; at the cake-autorate forum of OpenWrt and/or at github.com/lynxthecat/cake-autorate                                                                                                 
ERROR; 2023-01-26-14:38:55; 1674765535.852563; concurrent_read_integer() 10x misfires, with the following particulars:                                                               
ERROR; 2023-01-26-14:38:55; 1674765535.861426; caller=850 /root/cake-autorate/cake-autorate.sh, value= and path=/var/run/cake-autorate/primary/reflector_8-8-8-8_dl_owd_baseline_us                                    
LOAD; 2023-01-26-14:38:55; 1674765535.958016; 1674765535.957230; 39; 27; 89054; 10000                                                                                                                                              
LOAD; 2023-01-26-14:38:56; 1674765536.167978; 1674765536.167203; 45; 38; 89054; 10000                                                                                                                                       
LOAD; 2023-01-26-14:38:56; 1674765536.378001; 1674765536.377210; 62; 110; 89054; 10000                                                                                                                               
LOAD; 2023-01-26-14:38:56; 1674765536.588210; 1674765536.587430; 128; 34; 89054; 10000                                                                                                                                      
LOAD; 2023-01-26-14:38:56; 1674765536.798015; 1674765536.797234; 36; 21; 89054; 10000                                                                                                                                              
DEBUG; 2023-01-26-14:38:56; 1674765536.885736; no ping response from reflector: 9.9.9.10 within reflector_response_deadline: 1.0s                                                                                                  
DEBUG; 2023-01-26-14:38:56; 1674765536.894518; reflector=9.9.9.10, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3                                                          
DEBUG; 2023-01-26-14:38:56; 1674765536.906461; no ping response from reflector: 8.8.8.8 within reflector_response_deadline: 1.0s                                                                                              
DEBUG; 2023-01-26-14:38:56; 1674765536.915145; reflector=8.8.8.8, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3                                                                                          
DEBUG; 2023-01-26-14:38:56; 1674765536.927762; no ping response from reflector: 94.140.14.140 within reflector_response_deadline: 1.0s                                                                                      
DEBUG; 2023-01-26-14:38:56; 1674765536.936351; reflector=94.140.14.140, sum_reflector_offences=1 and reflector_misbehaving_detection_thr=3                                                                                         
DEBUG; 2023-01-26-14:38:56; 1674765536.948561; no ping response from reflector: 208.67.220.2 within reflector_response_deadline: 1.0s                                                                                 

After 10+ minutes still no change in CAKE rate. It is killing the fping process every few seconds.

All I can think of is if you could please pastebin complete log.

Unless anyone else has any ideas many thanks indeed and feel free just to killall -9 bash and fping.

I'll need to try to ponder what's happened here.

OK here's the paste of the logs

And now I am back in the "deep sleep" club, currently it hangs, when trying to kill:

Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.009494 Starting: monitor_reflector_responses_fping with PID: 2314
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.016511 monitor_pids[pinger]=2314 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.024904 no ping response from reflector: 185.228.168.10 within reflector_response_deadline: 1.0s
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.028769 reflector=185.228.168.10, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.032587 Warning: reflector: 185.228.168.10 seems to be misbehaving.
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.036425 Starting: replace_pinger_reflector with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.040045 replacing reflector: 185.228.168.10 with 9.9.9.9.
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.044747 Starting: kill_pinger with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.048798 Starting: kill_and_wait_by_pid_name with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.057125 pinger_pids[pinger]=2309 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 208.67.220.220 185.228.168.10 94.140.14.140 94.140.14.15 1.0.0.1 8.8.4.4
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.061076 Starting: debug_cmd with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.068347 debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=665 /root/cake-autorate/cake-autorate.sh; command=kill 2309; result=SUCCESS
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.072884 Starting: kill_and_wait_by_pid_name with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.081135 monitor_pids[pinger]=2314 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.085213 Starting: debug_cmd with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.090132 Starting: kill_monitor_reflector_responses_fping with PID: 2314
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.093154 debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=665 /root/cake-autorate/cake-autorate.sh; command=kill 2314; result=SUCCESS
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.112113 Starting: start_pinger with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.118558 Started pinger 0 with PID: 2345
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.126533 pinger_pids[pinger]=2345 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 208.67.220.220 9.9.9.9 94.140.14.140 94.140.14.15 1.0.0.1 8.8.4.4
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.131512 Starting: monitor_reflector_responses_fping with PID: 2350
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.136494 monitor_pids[pinger]=2350 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.143654 no ping response from reflector: 94.140.14.140 within reflector_response_deadline: 1.0s
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.147468 reflector=94.140.14.140, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.151208 Warning: reflector: 94.140.14.140 seems to be misbehaving.
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.155128 Starting: replace_pinger_reflector with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.158980 replacing reflector: 94.140.14.140 with 156.154.70.5.
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.162774 Starting: kill_pinger with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.166770 Starting: kill_and_wait_by_pid_name with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.175134 pinger_pids[pinger]=2345 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 208.67.220.220 9.9.9.9 94.140.14.140 94.140.14.15 1.0.0.1 8.8.4.4
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.178516 Starting: debug_cmd with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.189182 debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=665 /root/cake-autorate/cake-autorate.sh; command=kill 2345; result=SUCCESS
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.193674 Starting: kill_and_wait_by_pid_name with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.201992 monitor_pids[pinger]=2350 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.205951 Starting: debug_cmd with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.211411 Starting: kill_monitor_reflector_responses_fping with PID: 2350
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.213623 debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=665 /root/cake-autorate/cake-autorate.sh; command=kill 2350; result=SUCCESS
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.232278 Starting: start_pinger with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.238335 Started pinger 0 with PID: 2381
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.246405 pinger_pids[pinger]=2381 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 208.67.220.220 9.9.9.9 156.154.70.5 94.140.14.15 1.0.0.1 8.8.4.4
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.251698 Starting: monitor_reflector_responses_fping with PID: 2386
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.256621 monitor_pids[pinger]=2386 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.264047 no ping response from reflector: 94.140.14.15 within reflector_response_deadline: 1.0s
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.267657 reflector=94.140.14.15, sum_reflector_offences=0 and reflector_misbehaving_detection_thr=3
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.270963 Warning: reflector: 94.140.14.15 seems to be misbehaving.
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.274463 Starting: replace_pinger_reflector with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.278210 replacing reflector: 94.140.14.15 with 156.154.70.2.
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.281719 Starting: kill_pinger with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.285332 Starting: kill_and_wait_by_pid_name with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.294031 pinger_pids[pinger]=2381 cmdline: fping --timestamp --loop --period 300 --interval 50 --timeout 10000 208.67.220.220 9.9.9.9 156.154.70.5 94.140.14.15 1.0.0.1 8.8.4.4
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.297960 Starting: debug_cmd with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.305259 debug_cmd: err_silence=0; debug_msg=pinger_pids[pinger]; caller_id=665 /root/cake-autorate/cake-autorate.sh; command=kill 2381; result=SUCCESS
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.308989 Starting: kill_and_wait_by_pid_name with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.317445 monitor_pids[pinger]=2386 cmdline: /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.321185 Starting: debug_cmd with PID: 16450
Jan 25 09:30:51 turris cake-autorate.vdsl2: DEBUG: 1674639051.328122 debug_cmd: err_silence=0; debug_msg=monitor_pids[pinger]; caller_id=665 /root/cake-autorate/cake-autorate.sh; command=kill 2386; result=SUCCESS
Jan 25 09:39:06 turris cake-autorate.vdsl2: DEBUG: 1674639546.286159 log file maximum time: 30 minutes has elapsed so rotating log file
Jan 25 09:39:06 turris cake-autorate.vdsl2: DEBUG: 1674639546.289306 Starting: flush_log_fifo with PID: 12049
Jan 25 09:39:06 turris cake-autorate.vdsl2: DEBUG: 1674639546.303387 Starting: rotate_log_file with PID: 12049
Jan 25 09:39:06 turris cake-autorate.vdsl2: DEBUG: 1674639546.311160 Starting: print_headers with PID: 12049
Jan 25 10:09:06 turris cake-autorate.vdsl2: DEBUG: 1674641346.391894 log file maximum time: 30 minutes has elapsed so rotating log file
Jan 25 10:09:06 turris cake-autorate.vdsl2: DEBUG: 1674641346.395174 Starting: flush_log_fifo with PID: 12049
Jan 25 10:09:06 turris cake-autorate.vdsl2: DEBUG: 1674641346.409043 Starting: rotate_log_file with PID: 12049
Jan 25 10:09:06 turris cake-autorate.vdsl2: DEBUG: 1674641346.416759 Starting: print_headers with PID: 12049

and

22911 root        20   0  1576  1236   940 S   0.0  0.1 13:20.58 `- SCREEN -RR autorate
22913 root        20   0  1232   700   656 S   0.0  0.1  0:00.00 |  `- /bin/ash
12038 root        20   0  2128  1192   968 S   0.0  0.1  0:00.00 |     `- /bin/bash ./cake-autorate_launcher.sh
12042 root        20   0  2668  1688   924 S   0.0  0.2  7h29:00 |        `- /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
12044 root        20   0  2436  1412   900 S   0.0  0.1  0:00.00 |        |  `- /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
12049 root        20   0  2484  1508   944 S   0.0  0.1  1h15:37 |        |  `- /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
12072 root        20   0  2640  1632   900 S   1.9  0.2  2h25:43 |        |  `- /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
16450 root        20   0  2756  1756   900 S   0.0  0.2  0:24.98 |        |  `- /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
 2386 root        20   0  2640  1624   900 S   0.0  0.2  0:00.02 |        |     `- /bin/bash /root/cake-autorate/cake-autorate.sh /root/cake-autorate/cake-autorate_config.vdsl2.sh
12043 root        20   0   772   500   472 S   0.0  0.0  0:00.00 |        `- sleep inf

PID 2386 was not terminating:

root@turris:~/cake-autorate/20230126_2220_deep_sleep$ strace -s 1000 -y -p 2386
strace: Process 2386 attached
writev(1</tmp/run/cake-autorate/vdsl2/ping_fifo>, [{iov_base="1674639051.256490 208.67.220.220 0 8076 8300 267 223 8076 8300 267 223", iov_len=70}, {iov_base="\n", iov_len=1}], 2

But the main loop is waiting for the kill of maintain pingers and is not servicing /tmp/run/cake-autorate/vdsl2/ping_fifo
Manually kill -TERM 2386 returned autorate to do something again.

Mmmmh, it did restart fping, but it did not actually work, and I had to manually use kill -9 on all PIDs belonging to autorate....

1 Like

So it looks like the problem may relate to the ping_fifo? This is how that is used:

  • fping writes to pinger_0_fifo;
  • monitor process reads pinger_0_fifo and writes to ping_fifo; and
  • main loop reads from ping_fifo.

@patrakov can you think of a situation in which the fping process could block a kill? Or something else associated with the above sequence that might explain this deep sleep issue that I just can't seem to recreate on my system?

Any clue how I might recreate this deep sleep scenario on my system? That would be so useful if I could.

I'll have a careful think through the information above.

Did you manage to capture log from the event?

@gba thanks again for helping out here. What's your hardware/OpenWrt version by the way?

We will get to the bottom of this.


@juliank for faster download bursts you can just increase:

shaper_rate_adjust_up_load_high=1.01      # how rapidly to increase shaper rate upon high load detected 

Maybe try 1.02 or even 1.05. It may be beneficial in that situation to increase the ping resolution by increasing the number of pingers. But only if your router has spare CPU capacity.

Out of the box, perl autorate is pretty good, better then untweaked bash autorate for sure. Tweaked bash autorate is significantly better for uploads. Any tips how to adjust perl version?

EDIT: Notably jitter of perl is lower and I do get better download results vs bash autorate. Although I do see the perl version upload bursting up, it's very quick to clamp-down on bandwidth even though it's latency is set to 30ms (resulting latency is 16ms, 5ms on bufferbloat test).

tuned cake:


default perl:


1 Like

@tievolu is your man!

1 Like

@tievolu

Below is my configuration. I achieved higher upload speeds with increase_delay_after_decrease = 10.

# SQM Autorate configuration file
#
# - Property keys and values cannot contain whitespace
# - All text after a '#' is ignored
# - A property value can reference another key using '$'
#   e.g. ul_bw_idle_threshold = $ul_bw_minimum

wan_interface                   = wan

ul_interface.0                  = wan       # WAN
dl_interface.0                  = ifb4wan

dl_bw_minimum                   = 250000
dl_bw_standard                  = 590000
dl_bw_maximum                   = 750000

ul_bw_minimum                   = 18000
ul_bw_standard                  = 35000
ul_bw_maximum                   = 40000

ul_max_idle_latency             = 35
ul_max_loaded_latency           = 35
dl_max_idle_latency             = 35
dl_max_loaded_latency           = 35

reflectors_csv_file             = ./reflectors-americas.csv
number_of_reflectors            = 3
reflector_strikeout_threshold   = 1

log_file                        = /tmp/perl-autorate.log
log_details_on_bw_changes       = 1

latency_check_interval          = 0.2
#ul_bw_idle_threshold            = 10000
increase_delay_after_decrease   = 10

I LOVE that you guys are seeing the network and sawtooths at this level of detail. It is kind of like being a physicist able to speed himself up to see inside the electron shell of an atom.

For funzies please run a bandwidth test over on https://payne.taht.net and think about even better ways to plot stuff like this? We have libreqos successfully sampling at 10ms now. Fiddling with scatterplots, etc. If you can think of some way of leveraging your code and our simulation to help out here?, please send me an ssh key.

I kind of hope that once we get more folk running libreqos, we can attempt (at scale) measurements like sqm-autorate, and/or attempt to leverage passive measurements as we are doing in libreqos.io.

https://github.com/LibreQoE/LibreQoS is just x86 right now, with a whole lot of rust and python, I hope we can get it going on openwrt one day also.

You can find us in the #libreqos:matrix.org chatroom.

2 Likes

I wish there was autorate form AP as my wifi bandwidth is sometimes lower then my internet bandwidth. It seems to work if I set my laptop IP as a reflector but it only works when my laptop is online. Perhaps the script could be expanded to use client IPs with strong RSSI as reflectors?

1 Like

Only the syslog:

The following log file only shows log rotations, so the problem occurs pretty much at the end of the log file.

1 Like

I concur, anybody having ideas for the autorate plots, please let me know.

Just to state it explicitly, in my case there was no fping process any more...