From cdae9beff066cd11cdae2d6b10bbe329a0872c49 Mon Sep 17 00:00:00 2001 From: Marco d'Itri Date: Sun, 7 May 2023 17:56:43 +0200 Subject: [PATCH 1/3] implement logging the LCP RTT This change adds the lcp-rtt-file configuration option, which instructs pppd to add a timestamp to the data section of each LCP echo request frame and then log their round-trip time and any detected packet loss to a circular buffer in that file. Other programs then can asynchronously read the file and report statistics about the line. Signed-off-by: Marco d'Itri --- pppd/lcp.c | 175 +++++++++++++++++++++++++++++++++++++++++++++++++++- pppd/pppd.8 | 4 ++ 2 files changed, 178 insertions(+), 1 deletion(-) diff --git a/pppd/lcp.c b/pppd/lcp.c index c72c2ef90..d174b8fb5 100644 --- a/pppd/lcp.c +++ b/pppd/lcp.c @@ -47,6 +47,11 @@ #include #include #include +#include +#include +#include +#include +#include #include "pppd-private.h" #include "options.h" @@ -67,12 +72,22 @@ static void lcp_delayed_up(void *); +/* + * These definitions relate to the measurement and logging of round-trip + * time (RTT) of LCP echo-requests implemented in lcp_rtt_update_buffer(). + */ +#define LCP_RTT_MAGIC 0x19450425 +#define LCP_RTT_HEADER_LENGTH 4 +#define LCP_RTT_FILE_SIZE 8192 +#define LCP_RTT_ELEMENTS (LCP_RTT_FILE_SIZE / sizeof(u_int32_t) - LCP_RTT_HEADER_LENGTH) / 2 + /* * LCP-related command-line options. */ int lcp_echo_interval = 0; /* Interval between LCP echo-requests */ int lcp_echo_fails = 0; /* Tolerance to unanswered echo-requests */ bool lcp_echo_adaptive = 0; /* request echo only if the link was idle */ +char *lcp_rtt_file = NULL; /* measure the RTT of LCP echo-requests */ bool lax_recv = 0; /* accept control chars in asyncmap */ bool noendpoint = 0; /* don't send/accept endpoint discriminator */ @@ -152,6 +167,9 @@ static struct option lcp_option_list[] = { "Set time in seconds between LCP echo requests", OPT_PRIO }, { "lcp-echo-adaptive", o_bool, &lcp_echo_adaptive, "Suppress LCP echo requests if traffic was received", 1 }, + { "lcp-rtt-file", o_string, &lcp_rtt_file, + "Filename for logging the round-trip time of LCP echo requests", + OPT_PRIO | OPT_PRIV }, { "lcp-restart", o_int, &lcp_fsm[0].timeouttime, "Set time in seconds between LCP retransmissions", OPT_PRIO }, { "lcp-max-terminate", o_int, &lcp_fsm[0].maxtermtransmits, @@ -197,6 +215,8 @@ lcp_options lcp_hisoptions[NUM_PPP]; /* Options that we ack'd */ static int lcp_echos_pending = 0; /* Number of outstanding echo msgs */ static int lcp_echo_number = 0; /* ID number of next echo frame */ static int lcp_echo_timer_running = 0; /* set if a timer is running */ +static int lcp_rtt_file_fd = 0; /* fd for the opened LCP RTT file */ +static volatile u_int32_t *lcp_rtt_buffer = NULL; /* the mmap'ed LCP RTT file */ static u_char nak_buffer[PPP_MRU]; /* where we construct a nak packet */ @@ -2225,6 +2245,72 @@ LcpEchoTimeout (void *arg) } } +/* + * Log the round-trip time (RTT) of the received LCP echo-request. + * + * The header section at the beginning of lcp_rtt_file contains + * LCP_RTT_HEADER_LENGTH fields, each a u_int32_t in network byte order: + * [0] LCP_RTT_MAGIC + * [1] status (1: the file is open and is being written) + * [2] index of the most recently updated element + * [3] the value of the lcp-echo-interval parameter + * + * The header is followed by a ring buffer of LCP_RTT_ELEMENTS elements, each + * containing a pair of u_int32_t in network byte order with this content: + * [0] UNIX timestamp + * [1] bits 24-31: the number of lost LCP echo replies + * bits 0-23: the measured RTT in microseconds + * + * The timestamp is unsigned to support storing dates beyond 2038. + * + * Consumers of lcp_rtt_file are expected to: + * - read the complete file of arbitrary length + * - check the magic number + * - process the data elements starting at the index + * - ignore any elements with a timestamp of 0 + */ +static void +lcp_rtt_update_buffer (unsigned long rtt) +{ + volatile u_int32_t *const ring_buffer = lcp_rtt_buffer + + LCP_RTT_HEADER_LENGTH; + unsigned int next_entry, lost; + + /* choose the next entry where the data will be stored */ + if (ntohl(lcp_rtt_buffer[2]) >= (LCP_RTT_ELEMENTS - 1) * 2) + next_entry = 0; /* go back to the beginning */ + else + next_entry = ntohl(lcp_rtt_buffer[2]) + 2; /* use the next one */ + + /* update the data element */ + /* storing the timestamp in an *unsigned* long allows dates up to 2106 */ + ring_buffer[next_entry] = htonl((u_int32_t) time(NULL)); + lost = lcp_echos_pending - 1; + if (lost > 0xFF) + lost = 0xFF; /* truncate the lost packets count to 256 */ + if (rtt > 0xFFFFFF) + rtt = 0xFFFFFF; /* truncate the RTT to 16777216 */ + /* use bits 24-31 for the lost packets count and bits 0-23 for the RTT */ + ring_buffer[next_entry + 1] = htonl((u_int32_t) ((lost << 24) + rtt)); + + /* update the pointer to the (just updated) most current data element */ + lcp_rtt_buffer[2] = htonl(next_entry); + + /* In theory, CPUs implementing a weakly-consistent memory model do not + * guarantee that these three memory store operations to the buffer will + * be seen in the same order by the reader process. + * This means that a process reading the file could see the index + * having been updated before the element that the index points to had + * been written. + * But in practice we expect that the read(2) system call used by + * consumers processes is atomic with respect to the following msync(2) + * call, so we ignore the issue. + */ + + if (msync(lcp_rtt_buffer, LCP_RTT_FILE_SIZE, MS_ASYNC) < 0) + error("msync() for %s failed: %m", lcp_rtt_file); +} + /* * LcpEchoReply - LCP has received a reply to the echo */ @@ -2246,6 +2332,30 @@ lcp_received_echo_reply (fsm *f, int id, u_char *inp, int len) return; } + if (lcp_rtt_file_fd && len >= 16) { + long lcp_rtt_magic; + + /* + * If the magic word is found at the beginning of the data section + * of the frame then read the timestamp which follows and subtract + * it from the current time to compute the round trip time. + */ + GETLONG(lcp_rtt_magic, inp); + if (lcp_rtt_magic == LCP_RTT_MAGIC) { + struct timespec ts; + unsigned long req_sec, req_nsec, rtt; + + clock_gettime(CLOCK_MONOTONIC, &ts); + GETLONG(req_sec, inp); + GETLONG(req_nsec, inp); + /* compute the RTT in microseconds */ + rtt = (ts.tv_sec - req_sec) * 1000000 + + (ts.tv_nsec / 1000 - req_nsec / 1000); + /* log the RTT */ + lcp_rtt_update_buffer(rtt); + } + } + /* Reset the number of outstanding echo frames */ lcp_echos_pending = 0; } @@ -2258,7 +2368,7 @@ static void LcpSendEchoRequest (fsm *f) { u_int32_t lcp_magic; - u_char pkt[4], *pktp; + u_char pkt[16], *pktp; /* * Detect the failure of the peer at this point. @@ -2293,11 +2403,68 @@ LcpSendEchoRequest (fsm *f) lcp_magic = lcp_gotoptions[f->unit].magicnumber; pktp = pkt; PUTLONG(lcp_magic, pktp); + + /* Put a timestamp in the data section of the frame */ + if (lcp_rtt_file_fd) { + struct timespec ts; + + PUTLONG(LCP_RTT_MAGIC, pktp); + clock_gettime(CLOCK_MONOTONIC, &ts); + PUTLONG((u_int32_t)ts.tv_sec, pktp); + PUTLONG((u_int32_t)ts.tv_nsec, pktp); + } + fsm_sdata(f, ECHOREQ, lcp_echo_number++ & 0xFF, pkt, pktp - pkt); ++lcp_echos_pending; } } +static void +lcp_rtt_open_file (void) +{ + if (!lcp_rtt_file) + return; + + lcp_rtt_file_fd = open(lcp_rtt_file, O_RDWR | O_CREAT, 0644); + if (lcp_rtt_file_fd < 0) { + error("Can't open the RTT log file %s: %m", lcp_rtt_file); + lcp_rtt_file_fd = 0; + return; + } + + if (ftruncate(lcp_rtt_file_fd, LCP_RTT_FILE_SIZE) < 0) + fatal("ftruncate() of %s failed: %m", lcp_rtt_file); + lcp_rtt_buffer = mmap(0, LCP_RTT_FILE_SIZE, PROT_READ | PROT_WRITE, + MAP_SHARED, lcp_rtt_file_fd, 0); + if (lcp_rtt_buffer == MAP_FAILED) + fatal("mmap() of %s failed: %m", lcp_rtt_file); + + /* initialize the ring buffer */ + if (lcp_rtt_buffer[0] != htonl(LCP_RTT_MAGIC)) { + memset(lcp_rtt_buffer, 0, LCP_RTT_FILE_SIZE); + lcp_rtt_buffer[0] = htonl(LCP_RTT_MAGIC); + } + + lcp_rtt_buffer[3] = htonl(lcp_echo_interval); + lcp_rtt_buffer[1] = htonl(1); /* status: LCP up, file opened */ +} + +static void +lcp_rtt_close_file (void) +{ + if (!lcp_rtt_file_fd) + return; + + lcp_rtt_buffer[1] = htonl(0); /* status: LCP down, file closed */ + + if (munmap(lcp_rtt_buffer, LCP_RTT_FILE_SIZE) < 0) + error("munmap() of %s failed: %m", lcp_rtt_file); + if (close(lcp_rtt_file_fd) < 0) + error("close() of %s failed: %m", lcp_rtt_file); + lcp_rtt_buffer = NULL; + lcp_rtt_file_fd = 0; +} + /* * lcp_echo_lowerup - Start the timer for the LCP frame */ @@ -2311,6 +2478,9 @@ lcp_echo_lowerup (int unit) lcp_echos_pending = 0; lcp_echo_number = 0; lcp_echo_timer_running = 0; + + /* Open the file where the LCP RTT data will be logged */ + lcp_rtt_open_file(); /* If a timeout interval is specified then start the timer */ if (lcp_echo_interval != 0) @@ -2330,4 +2500,7 @@ lcp_echo_lowerdown (int unit) UNTIMEOUT (LcpEchoTimeout, f); lcp_echo_timer_running = 0; } + + /* Close the file containing the LCP RTT data */ + lcp_rtt_close_file(); } diff --git a/pppd/pppd.8 b/pppd/pppd.8 index 79b5bea5c..6bb28b296 100644 --- a/pppd/pppd.8 +++ b/pppd/pppd.8 @@ -637,6 +637,10 @@ Set the maximum number of LCP terminate-request transmissions to Set the LCP restart interval (retransmission timeout) to \fIn\fR seconds (default 3). .TP +.B lcp\-rtt\-file \fIfilename +Sets the file where the round-trip time (RTT) of LCP echo-request frames +will be logged. +.TP .B linkname \fIname\fR Sets the logical name of the link to \fIname\fR. Pppd will create a file named \fBppp\-\fIname\fB.pid\fR in /var/run (or /etc/ppp on some From 4f4f54d7dfd3b3c0e12eae8ca76f91e2b5f78602 Mon Sep 17 00:00:00 2001 From: Marco d'Itri Date: Sun, 7 May 2023 17:59:36 +0200 Subject: [PATCH 2/3] scripts/lcp_rtt_dump: dump the LCP RTT log Signed-off-by: Marco d'Itri --- scripts/lcp_rtt_dump | 81 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 81 insertions(+) create mode 100755 scripts/lcp_rtt_dump diff --git a/scripts/lcp_rtt_dump b/scripts/lcp_rtt_dump new file mode 100755 index 000000000..7898f084e --- /dev/null +++ b/scripts/lcp_rtt_dump @@ -0,0 +1,81 @@ +#!/usr/bin/perl +# vim: shiftwidth=4 tabstop=4 +# +# This program dumps to standard output the content of the file written +# by pppd's lcp-rtt-file configuration option. +# +# Copyright (C) Marco d'Itri +# +# This program is free software; you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation; either version 2 of the License, or +# (at your option) any later version. + +use v5.14; +use warnings; +use autodie; + +use POSIX qw(strftime); + +{ + my $data = read_data($ARGV[0] || '/run/ppp-rtt.data'); + die "The data file is invalid!\n" if not $data; + dump_data($data); +} + +sub dump_data { + my ($s) = @_; + + say "status: $s->{status}"; + say "interval: $s->{echo_interval}"; + say "position: $s->{position}"; + say 'elements: ' . scalar(@{ $s->{data} }); + say ''; + + foreach (my $i= 0; $i < @{ $s->{data} }; $i++) { + my $date = strftime('%F %T', localtime($s->{data}->[$i]->[0])); + print "$i\t$date\t$s->{data}->[$i]->[1]\t$s->{data}->[$i]->[2]\n"; + } +} + +sub read_data { + my ($file) = @_; + + my $data; + open(my $fh, '<', $file); + binmode($fh); + my $bytes_read; + do { + $bytes_read = sysread($fh, $data, 8192, length($data)); + } while ($bytes_read == 8192); + close($fh); + + my ($magic, $status, $position, $echo_interval, $rest) + = unpack('NNNN a*', $data); + return undef if $magic != 0x19450425; + + # the position is relative to the C array, not to the logical entries + $position /= 2; + + my @rawdata = unpack('(N C a3)*', $rest); + my @data; + while (my ($time, $loss, $rtt) = splice(@rawdata, 0, 3)) { + push(@data, [ $time, unpack('N', "\000$rtt"), $loss ]); + } + + if (0) { + @data = + # skip any "empty" (null) entries + grep { $_->[0] } + # rearrange the list in chronological order + (@data[$position+1 .. $#data], @data[0 .. $position]); + } + + return { + status => $status, + echo_interval => $echo_interval, + position => $position, + data => \@data, + }; +} + From d7f54a412116db68855c19394c0ef754eace8c7d Mon Sep 17 00:00:00 2001 From: Marco d'Itri Date: Sun, 24 Sep 2023 12:03:04 +0200 Subject: [PATCH 3/3] scripts/lcp_rtt_exporter: Prometheus exporter for the LCP RTT data Signed-off-by: Marco d'Itri --- scripts/lcp_rtt_exporter | 108 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 108 insertions(+) create mode 100644 scripts/lcp_rtt_exporter diff --git a/scripts/lcp_rtt_exporter b/scripts/lcp_rtt_exporter new file mode 100644 index 000000000..6fab745f2 --- /dev/null +++ b/scripts/lcp_rtt_exporter @@ -0,0 +1,108 @@ +#!/usr/bin/perl +# vim: shiftwidth=4 tabstop=4 +# +# This CGI program is a Prometheus exporter for pppd's lcp-rtt-file feature. +# +# Copyright (C) Marco d'Itri +# +# This program is free software; you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation; either version 2 of the License, or +# (at your option) any later version. + +use v5.14; +use warnings; +use autodie; + +use List::Util qw(sum max min); + +{ + my $data = read_data('/run/ppp-rtt.data'); + my $stats = compute_statistics($data, 60); + + my $s = metrics($stats); + + print "Content-type: text/plain\n\n$s"; + exit; +} + +sub metrics { + my ($stats) = @_; + + my $s = <{status} +END + foreach (qw(average min max loss)) { + next if not exists $stats->{$_}; + $s .= <{$_} +END + } + + return $s; +} + +sub compute_statistics { + my ($data, $length) = @_; + + my $cutoff = time() - $length; + my @e = grep { $_->[0] >= $cutoff } @{ $data->{data} }; + return { status => -1 } if not @e; # no data + + my $average = (sum map { $_->[1] } @e) / scalar(@e); + my $min = min map { $_->[1] } @e; + my $max = max map { $_->[1] } @e; + my $loss = sum map { $_->[2] } @e; + + return { + status => $data->{status}, + average => $average, + min => $min, + max => $max, + loss => $loss, + }; +} + +sub read_data { + my ($file) = @_; + + my $data; + open(my $fh, '<', $file); + binmode($fh); + my $bytes_read; + do { + $bytes_read = sysread($fh, $data, 8192, length($data)); + } while ($bytes_read == 8192); + close($fh); + + my ($magic, $status, $position, $echo_interval, $rest) + = unpack('NNNN a*', $data); + return undef if $magic != 0x19450425; + + # the position is relative to the C array, not to the logical entries + $position /= 2; + + my @rawdata = unpack('(N C a3)*', $rest); + my @data; + while (my ($time, $loss, $rtt) = splice(@rawdata, 0, 3)) { + push(@data, [ $time, unpack('N', "\000$rtt"), $loss ]); + } + + @data = + # skip any "empty" (null) entries + grep { $_->[0] } + # rearrange the list in chronological order + (@data[$position+1 .. $#data], @data[0 .. $position]); + + return { + status => $status, + echo_interval => $echo_interval, + position => $position, + data => \@data, + }; +} +