Bug #8477
closedGateway latency, units used inconsistently.
100%
Description
When a gateway alarm is triggered or cleared is is reported in the system log using milliseconds (ms) but the gateway log using microseconds (us).
System log:
Apr 22 07:32:13 rc.gateway_alarm 84386 >>> Gateway alarm: OPT4_VPNV4 (Addr:172.27.114.129 Alarm:0 RTT:120183ms RTTsd:634ms Loss:0%)
Gateway log:
Apr 22 07:32:13 dpinger OPT4_VPNV4 172.27.114.129: Clear latency 120183us stddev 634us loss 0%
That value looks to be clearly in microseconds.
Updated by Anonymous over 6 years ago
- Status changed from New to Assigned
- Assignee set to Anonymous
Updated by Anonymous over 6 years ago
- Status changed from Assigned to Feedback
- % Done changed from 0 to 100
Applied in changeset 040a1579e474290abfc7a4a445e310ce8e462847.
Updated by → luckman212 over 6 years ago
Since I think "ms" is much more widely used and easier to comprehend, how about using
echo ">>> Gateway alarm: ${GW} (Addr:${alarm_addr} Alarm:${alarm_flag} RTT:$( expr ${alarm_rtt} / 1000 )ms RTTsd:$( expr ${alarm_rttsd} / 1000 )ms Loss:${alarm_loss}%)" | /usr/bin/logger -p daemon.info -i -t rc.gateway_alarm
instead?
Updated by Steve Wheeler over 6 years ago
System log now shows:
Jul 22 19:49:56 rc.gateway_alarm 12028 >>> Gateway alarm: WAN_DHCP (Addr:172.21.16.1 Alarm:1 RTT:196us RTTsd:17us Loss:22%)
And gateway log shows:
Jul 22 19:49:56 dpinger WAN_DHCP 172.21.16.1: Alarm latency 196us stddev 17us loss 22%
So consistent there. But the initial output and config is inb milliseconds:
Jul 22 17:53:02 dpinger send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 172.21.16.1 bind_addr 172.21.16.82 identifier "WAN_DHCP "
Milliseconds is the expected unit there IMO.
Updated by → luckman212 over 6 years ago
Steve:
For the first case (rc.gateway_alarm), how about the change I suggested over on the github commit?
https://github.com/pfsense/pfsense/commit/040a1579e474290abfc7a4a445e310ce8e462847#commitcomment-29773284
For the other 2 (dpinger) we need to update the way dpinger.c outputs to the log, to similarly show in ms if ms > 1, otherwise show in usec
https://github.com/dennypage/dpinger/blob/master/dpinger.c#L660
https://github.com/dennypage/dpinger/blob/master/dpinger.c#L1412
It should be pretty easy to add a quick function to dpinger.c and use it when logging. I could try to make it myself, but Denny could probably do it in his sleep
Updated by Steve Wheeler over 6 years ago
Personally I can live with seeing '0.196ms' there. Let's see what Stephen suggests when he gets gets the feedback.
However I can see the reasoning behind using µs everywhere.
Updated by Anonymous over 6 years ago
I'll work on making it milliseconds for everything to be consistent. I added the code you suggested Luke for the gateway alarm I am however using the format 0.xxxms instead of us just to try and keep it as much ms as possible.
print_rtt() { usec=$1 if [ "$usec" -lt "1000" ]; then retval="0.${usec}ms" else retval="$( expr ${usec} / 1000 )ms" fi echo $retval }
Updated by Anonymous over 6 years ago
Change made here 37be6b260f8b90393d994c40e2db34925acaa451. I'll have to look into the best way to get that into dpinger as well.
Updated by → luckman212 over 6 years ago
Stephen, That change looks problematic.
I made a comment on the commit but adding one here for completeness.
Example, if the rtt is 10usec, it will print as 0.10ms which actually == 100usec.
If you want everything in ms explicitly, you don't need the if anymore, just use something like
print_rtt() { usec_to_ms="$( expr $1 / 1000 )ms" echo $usec_to_ms }
or maybe just
print_rtt() { echo "$( expr $1 / 1000 )ms" }
Updated by Anonymous over 6 years ago
Good catch. I'll change that. Do we care about decimal precision? anything under 1 ms will round to 0. I don't know if this matters or not. I can use bc to get some decimal precision if needs be. I haven't actually used these alarms so I don't know what is expected here.
Updated by → luckman212 over 6 years ago
Good point about expr only doing integer math. For floats we could use bc
print_rtt() { usec=$1 usec_to_ms=$( echo "scale=3; ${usec}/1000" | bc -l ) echo "${usec_to_ms}ms" }
Updated by Anonymous over 6 years ago
Awesome, Thanks for your help. I made the change you have above to the code here. 21daa13ee2642a5f4821382a46be2dfc71ba2b5a
Updated by → luckman212 over 6 years ago
I made a rough PR for dpinger.c that also replicates this "usec to ms" format change. Minimal testing, but it works on my end. Submitted a PR here:
https://github.com/dennypage/dpinger/pull/32
Updated by Vladimir Lind over 6 years ago
- Status changed from Feedback to Confirmed
Tested on 2.4.4-DEVELOPMENT (arm) built on Thu Aug 02 10:54:34 EDT 2018
Looks good.
GW log:
Aug 10 14:25:12 dpinger OPENVPN_SERVER_VPNV4 10.254.254.2: Alarm latency 5364us stddev 1676us loss 21%
Syslog:
Aug 10 14:25:12 rc.gateway_alarm 69623 >>> Gateway alarm: OPENVPN_SERVER_VPNV4 (Addr:10.254.254.2 Alarm:1 RTT:5.364ms RTTsd:1.676ms Loss:21%)
Updated by Vladimir Lind over 6 years ago
- Status changed from Confirmed to Resolved
Updated by → luckman212 over 6 years ago
Before this gets closed out, can the PR 32 for the dpinger.c update get merged as well so everything is consistent (ms)?