Project

General

Profile

Bug #8477

Gateway latency, units used inconsistently.

Added by Steve Wheeler about 1 year ago. Updated 10 months ago.

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

100%

Estimated time:
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.

Associated revisions

Revision 040a1579 (diff)
Added by Stephen Jones 10 months ago

Changed ms to us Fixes #8477

Revision 37be6b26 (diff)
Added by Stephen Jones 10 months ago

Change us to ms for gateway alarm.

Fixes #8477 looking to be more consitent changed to use ms for gateway alarm.
Thanks to Luke Hamburg for helping with this and the code idea.
Keeping it as 0.xxxms for under 1 millisecond responses.
Just to stay ms as much as possible.

History

#1 Updated by Anonymous 10 months ago

  • Status changed from New to Assigned
  • Assignee set to Anonymous

#2 Updated by Anonymous 10 months ago

  • Status changed from Assigned to Feedback
  • % Done changed from 0 to 100

#3 Updated by Luke Hamburg 10 months 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?

#4 Updated by Steve Wheeler 10 months 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.

#5 Updated by Luke Hamburg 10 months 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

#6 Updated by Steve Wheeler 10 months 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.

#7 Updated by Anonymous 10 months 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
}

#8 Updated by Anonymous 10 months ago

Change made here 37be6b260f8b90393d994c40e2db34925acaa451. I'll have to look into the best way to get that into dpinger as well.

#9 Updated by Luke Hamburg 10 months 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" 
}

#10 Updated by Anonymous 10 months 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.

#11 Updated by Luke Hamburg 10 months 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" 
}

#12 Updated by Anonymous 10 months ago

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

#13 Updated by Luke Hamburg 10 months 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

#14 Updated by Vladimir Lind 10 months 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%)

#15 Updated by Vladimir Lind 10 months ago

  • Status changed from Confirmed to Resolved

#16 Updated by Luke Hamburg 10 months ago

Before this gets closed out, can the PR 32 for the dpinger.c update get merged as well so everything is consistent (ms)?

Also available in: Atom PDF