Project

General

Profile

Actions

Bug #8477

closed

Gateway latency, units used inconsistently.

Added by Steve Wheeler over 6 years ago. Updated over 6 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
Logging
Target version:
Start date:
04/22/2018
Due date:
% Done:

100%

Estimated time:
Plus Target Version:
Release Notes:
Affected Version:
2.4.x
Affected Architecture:
All

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.

Actions #1

Updated by Anonymous over 6 years ago

  • Status changed from New to Assigned
  • Assignee set to Anonymous
Actions #2

Updated by Anonymous over 6 years ago

  • Status changed from Assigned to Feedback
  • % Done changed from 0 to 100
Actions #3

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?

Actions #4

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.

Actions #5

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

Actions #6

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.

Actions #7

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
}

Actions #8

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.

Actions #9

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" 
}
Actions #10

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.

Actions #11

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" 
}
Actions #12

Updated by Anonymous over 6 years ago

Awesome, Thanks for your help. I made the change you have above to the code here. 21daa13ee2642a5f4821382a46be2dfc71ba2b5a

Actions #13

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

Actions #14

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%)

Actions #15

Updated by Vladimir Lind over 6 years ago

  • Status changed from Confirmed to Resolved
Actions #16

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)?

Actions

Also available in: Atom PDF