Trouble running the "owd" script

richb-hanover commented 2 years ago

I am having problems running the owd branch as-is from the repo

I got a hping3 binary from Lochnair. It seemed to install without problems
I needed to get hping_parser.awk - I got it from https://github.com/Fail-Safe/hping3-parser/blob/main/hping_parser.awk
Now the script runs, but I get error messages: The "No Response. Skipping this reflector..." lines and the summary line with the time stamp repeat every second. (see below)

Running hping3 from the command line gives:

root@D-Link-DIR-878:~# hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1
HPING 46.227.200.54 (wan 46.227.200.54): icmp mode set, 28 headers + 0 data bytes
len=46 ip=46.227.200.54 ttl=52 id=39629 icmp_seq=0 rtt=94.8 ms
ICMP timestamp: Originate=44669708 Receive=44669757 Transmit=44669757
ICMP timestamp RTT tsrtt=95

--- 46.227.200.54 hping statistic ---
1 packets tramitted, 1 packets received, 0% packet loss
round-trip min/avg/max = 94.8/94.8/94.8 ms

What other information can I provide to diagnose this? Thanks.

# running sqm-autorate.sh, showing "No Response..." error messages
root@D-Link-DIR-878:~# ./sqm-autorate.sh
rx_bytes_path: /sys/class/net/ifb4wan/statistics/tx_bytes
tx_bytes_path: /sys/class/net/wan/statistics/tx_bytes
                 log_time;       rx_load;       tx_load;  min_dl_delta;  min_ul_delta;   cur_dl_rate;   cur_ul_rate;              ;
46.227.200.54 No Response. Skipping this reflector.
194.242.2.2 No Response. Skipping this reflector.
194.242.2.3 No Response. Skipping this reflector.
46.227.200.55 No Response. Skipping this reflector.
149.112.112.11 No Response. Skipping this reflector.
149.112.112.112 No Response. Skipping this reflector.
193.19.108.2 No Response. Skipping this reflector.
9.9.9.9 No Response. Skipping this reflector.
193.19.108.3 No Response. Skipping this reflector.
9.9.9.10 No Response. Skipping this reflector.
9.9.9.11 No Response. Skipping this reflector.
149.112.112.10 No Response. Skipping this reflector.
 20211223T064600.011925227;          0.00;          0.00;      10000.00;      10000.00;      25175.00;      25175.00;
46.227.200.54 No Response. Skipping this reflector.
194.242.2.2 No Response. Skipping this reflector.
... repeated every second ...

richb-hanover commented 2 years ago

Update: adding the timeout 0.8 command causes hping_parser.awk to output 9999999, which triggers the "No Response..." messages. Thoughts?

root@D-Link-DIR-878:~# timeout 0.8 hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null | ./hping_parser.awk
999999999 999999999

lynxthecat commented 2 years ago

How about when you omit the timeout?

richb-hanover commented 2 years ago

root@D-Link-DIR-878:~# timeout 0.8  hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null | ./hping_parser.awk
999999999 999999999
root@D-Link-DIR-878:~#  hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null | ./hping_parser.awk
51 44

lynxthecat commented 2 years ago

What about just:

root@OpenWrt:~# timeout 0.8 hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null HPING 46.227.200.54 (wan 46.227.200.54): icmp mode set, 28 headers + 0 data bytes len=46 ip=46.227.200.54 ttl=54 id=59171 icmp_seq=0 rtt=59.3 ms ICMP timestamp: Originate=59583033 Receive=59583065 Transmit=59583065 ICMP timestamp RTT tsrtt=60

lynxthecat commented 2 years ago

Are you using: coreutils-timeout?

https://openwrt.org/packages/pkgdata/coreutils-timeout

richb-hanover commented 2 years ago

Are you using: coreutils-timeout?

No, somehow that had got uninstalled. Re-installing got the script to work. THANKS!

lynxthecat commented 2 years ago

Does it work roughly for you? Could you please post data on the main thread showing how script ramps up bandwidth on saturation (not with reflector data just the main red lines) by enabling plotting output and disabling reflector output?

richb-hanover commented 2 years ago

I got it working, then family arrived. I'll check in the AM.

richb-hanover commented 2 years ago

Update: On further investigation, I believe there's a mismatch between the output of my version of hping3 and hping_parser.awk. The latter is not producing credible values. So I created a simpler test to display the parsed values from a single hping3 command. It returned:

√ shell-sqm-autorate % ./hping-parser-test.awk < hping-test.txt
$1 =52
$2 id=23523
$3 icmp_seq=0
$4 rtt=94.4            <== RTT is #4 (not #5) in hping_parser.awk
$5 ms
$6 ICMP
$7 timestamp:
$8 Originate=44625709  <== 8 (not 9)
$9 Receive=44625759    <== (same)
$10 Transmit=44625759  <== (same)
$11 ICMP
$12 timestamp

Here's the output of my hping3 command:

root@D-Link-DIR-878:~# hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null
HPING 46.227.200.54 (wan 46.227.200.54): icmp mode set, 28 headers + 0 data bytes
len=46 ip=46.227.200.54 ttl=52 id=23523 icmp_seq=0 rtt=94.4 ms
ICMP timestamp: Originate=44625709 Receive=44625759 Transmit=44625759
ICMP timestamp RTT tsrtt=94

Here's the hping-parser-test.awk script itself

#!/usr/bin/awk -f

# hping_parser_test.awk
# Test the output of hping3 - sample data

# root@D-Link-DIR-878:~# hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null
# HPING 46.227.200.54 (wan 46.227.200.54): icmp mode set, 28 headers + 0 data bytes
# len=46 ip=46.227.200.54 ttl=52 id=23523 icmp_seq=0 rtt=94.4 ms
# ICMP timestamp: Originate=44625709 Receive=44625759 Transmit=44625759
# ICMP timestamp RTT tsrtt=94

# Set defaults for the record set
BEGIN {
    RS = "len=[0-9]+ "
    FS = " "
}

# This is to skip the "header" line from hping3 output. This replaces the previous 'tail -n+2' pipe.
NR == 1 { next }

# Main loop to iterate over each record in the record set
{
    # no main loop
}

# Final actions once record set has been iterated
END {
    print "$1", $1
    print "$2", $2
    print "$3", $3
    print "$4", $4
    print "$5", $5
    print "$6", $6
    print "$7", $7
    print "$8", $8
    print "$9", $9
    print "$10", $10
    print "$11", $11
    print "$12", $12
}

lynxthecat commented 2 years ago

Here is what I see:

root@OpenWrt:~# hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null
HPING 46.227.200.54 (wan 46.227.200.54): icmp mode set, 28 headers + 0 data bytes
len=46 ip=46.227.200.54 ttl=54 id=38265 icmp_seq=0 rtt=59.4 ms
ICMP timestamp: Originate=48277503 Receive=48277517 Transmit=48277517
ICMP timestamp RTT tsrtt=60

root@OpenWrt:~# hping3 46.227.200.54 --icmp --icmp-ts -i u1000 -c 1 2> /dev/null | ./hping-parser-test.awk
$1 ip=46.227.200.54
$2 ttl=54
$3 id=27539
$4 icmp_seq=0
$5 rtt=59.6
$6 ms
$7 ICMP
$8 timestamp:
$9 Originate=48105013
$10 Receive=48105026
$11 Transmit=48105026
$12 ICMP

richb-hanover commented 2 years ago

Here is what I see:

Hmmm... I also see the same result when I run that command on the router. One of those mysteries I was speaking about.

But I am truly stepping away from this for a day (Those pesky grandchildren keep asking me questions, and Bufferbloat is not an engaging bedtime story... :-) Thanks.

lynxthecat / cake-autorate

Trouble running the "owd" script #12