Add millisecond resolution to log timestamps
This change adds millisecond resolution to the timestamp written
on RMR stderr messages.
The change also allows the verbose control file specified by the
environment variable RMR_VCTL_FILE to be created and populated
after the application starts. In addition, if no variable is
supplied, RMR will now use a default control file (/tmp/rmr.v)
to allow debugging to be enabled without requireing an application
restart.
Issue-ID: RIC-627
Signed-off-by: E. Scott Daniels <daniels@research.att.com>
Change-Id: I207150679370add11fcdeef381ff453b28e701db
diff --git a/CHANGES_CORE.txt b/CHANGES_CORE.txt
index e59da47..5be9139 100644
--- a/CHANGES_CORE.txt
+++ b/CHANGES_CORE.txt
@@ -5,7 +5,19 @@
# API and build change and fix summaries. Doc corrections
# and/or changes are not mentioned here; see the commit messages.
-2021 January21; Version 4.5.2
+2021 February 08; Version 4.6.0
+ Enhanced to use millisecond based timestamps when writing log messages.
+ (RIC-627)
+
+ Enhanced to eliminate the reqirement that the file specified by the
+ RMR_VCTL_FILE environment variable exist when RMR is initialised. RMR
+ will correctly find this file if it is created after initialisation.
+ Further, if the environment variable is not given, the user may create
+ and populate /tmp/rmr.v at any time and the contents of this file will
+ be used as if it were supplied via the environment variable. This should
+ make debugging in existing containers easier.
+
+2021 January 21; Version 4.5.2
Fixes the excessive TCP session bug when sending to a slow receiver
and a related segment fault because of too many open file descriptors.
(RIC-735)
diff --git a/CMakeLists.txt b/CMakeLists.txt
index 5cd177e..be0e448 100644
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -40,8 +40,8 @@
cmake_minimum_required( VERSION 3.5 )
set( major_version "4" ) # should be automatically populated from git tag later, but until CI process sets a tag we use this
-set( minor_version "5" )
-set( patch_level "2" )
+set( minor_version "6" )
+set( patch_level "0" )
set( install_root "${CMAKE_INSTALL_PREFIX}" )
set( install_inc "include/rmr" )
diff --git a/src/rmr/common/src/logging.c b/src/rmr/common/src/logging.c
index 56457f7..f87b65d 100644
--- a/src/rmr/common/src/logging.c
+++ b/src/rmr/common/src/logging.c
@@ -90,6 +90,23 @@
static char* log_situations[RMR_VL_DEBUG+1];
/*
+ Return the current unix timestamp as milliseconds since the epoch.
+ If time() returns 515300400, this function will add three didgets which
+ represent the milliseconds: 515300400123 (515300400.123).
+*/
+static long long mstime( ) {
+ struct timespec now;
+ long long rv = 0;
+
+ if( clock_gettime( CLOCK_REALTIME, &now ) ) {
+ return rv;
+ }
+
+ rv = ((long long) now.tv_sec * 1000) + ( (long long) now.tv_nsec/1000000 );
+ return rv;
+}
+
+/*
Initialise logging. Returns the current log level.
*/
extern int rmr_vlog_init( ) {
@@ -146,7 +163,7 @@
}
memset( msg, 0, sizeof( msg ) ); // logging is slow; this ensures 0 term if msg is too large
- hlen = snprintf( msg, sizeof( msg ), "%ld %d/RMR [%s] ", (long) time( NULL ), log_pid, log_situations[write_level] );
+ hlen = snprintf( msg, sizeof( msg ), "%lld %d/RMR [%s] ", mstime( ), log_pid, log_situations[write_level] );
if( hlen > sizeof( msg ) - 1024 ) { // should never happen, but be parinoid
return;
}
@@ -185,7 +202,7 @@
write_level = RMR_VL_DEBUG;
}
- hlen = snprintf( msg, sizeof( msg ), "%ld %d/RMR [%s] ", (long) time( NULL ), log_pid, log_situations[write_level] );
+ hlen = snprintf( msg, sizeof( msg ), "%lld %d/RMR [%s] ", mstime( ), log_pid, log_situations[write_level] );
body = msg + hlen;
va_start( argp, fmt ); // suss out parm past fmt
@@ -210,4 +227,16 @@
}
}
+#ifdef QUICK_TEST
+/*
+ Quick tests are some simple "pre" unit tests.
+ Compile with:
+ gcc -DQUICK_TEST=1 logging.c
+*/
+int main( ) {
+ printf( "mstime=%lld unix=%ld\n", mstime(), (long) time( NULL ) );
+}
+#endif
+
+
#endif
diff --git a/src/rmr/common/src/rtc_static.c b/src/rmr/common/src/rtc_static.c
index 8fe852d..2525342 100644
--- a/src/rmr/common/src/rtc_static.c
+++ b/src/rmr/common/src/rtc_static.c
@@ -53,13 +53,58 @@
// ------------------------------------------------------------------------------------------------
/*
+ Opens the vlevel control file if needed and reads the vlevel from it.
+ The file is rewound if already open so that external updates are captured.
+ The current level is returnd; 0 on error.
+
+ The environment variable (ENV_VERBOSE_FILE) is used to supply the file to
+ open and read. If missing, we will try /tmp/rmr.v. We will try to open the file
+ on each call if not alrady open; this allows the value to be supplied after
+ start which helps debugging.
+
+ If close_file is true, then we will close the open vfd and return 0;
+*/
+extern int refresh_vlevel( int close_file ) {
+ static int vfd = -1;
+
+ char* eptr;
+ char wbuf[128]; // read buffer; MUST be 11 or greater
+ int vlevel = 0;
+
+ if( close_file ) {
+ if( vfd >= 0 ) {
+ close( vfd );
+ vfd = -1;
+ }
+ return 0;
+ }
+
+ if( vfd < 0 ) { // attempt to find/open on all calls if not open
+ if( (eptr = getenv( ENV_VERBOSE_FILE )) != NULL ) {
+ vfd = open( eptr, O_RDONLY );
+ } else {
+ vfd = open( "/tmp/rmr.v", O_RDONLY );
+ }
+ if( vfd < 0 ) {
+ return 0;
+ }
+ }
+
+ memset( wbuf, 0, sizeof( char ) * 11 ); // ensure what we read will be nil terminated
+ if( lseek( vfd, 0, SEEK_SET ) == 0 && read( vfd, wbuf, 10 ) > 0 ) {
+ vlevel = atoi( wbuf );
+ }
+
+ return vlevel;
+}
+
+/*
Loop forever (assuming we're running in a pthread reading the static table
every minute or so.
*/
static void* rtc_file( void* vctx ) {
uta_ctx_t* ctx; // context user has -- where we pin the route table
char* eptr;
- int vfd = -1; // verbose file des if we have one
int vlevel = 0; // how chatty we should be 0== no nattering allowed
char wbuf[256];
@@ -69,46 +114,19 @@
return NULL;
}
- if( (eptr = getenv( ENV_VERBOSE_FILE )) != NULL ) {
- vfd = open( eptr, O_RDONLY );
- }
-
ctx->flags |= CFL_NO_RTACK; // no attempt to ack when reading from a file
while( 1 ) {
- if( vfd >= 0 ) {
- memset( wbuf, 0, sizeof( char ) * 11 );
- if( lseek( vfd, 0, SEEK_SET ) == 0 && read( vfd, wbuf, 10 ) > 0 ) {
- vlevel = atoi( wbuf );
- }
- }
-
+ vlevel = refresh_vlevel( 0 );
read_static_rt( ctx, vlevel ); // seed the route table if one provided
if( ctx->shutdown != 0 ) { // allow for graceful termination and unit testing
- if( vfd >= 0 ) {
- close( vfd );
- }
+ refresh_vlevel( 1 ); // close the verbose file if open
return NULL;
}
sleep( 60 );
}
}
-static int refresh_vlevel( int vfd ) {
- int vlevel = 0;
- char rbuf[128];
-
- if( vfd >= 0 ) { // if file is open, read current value
- rbuf[0] = 0;
- memset( rbuf, 0, sizeof( char ) * 11 );
- if( lseek( vfd, 0, SEEK_SET ) == 0 && read( vfd, rbuf, 10 ) > 0 ) {
- vlevel = atoi( rbuf );
- }
- }
-
- return vlevel;
-}
-
/*
Rtc_parse_msg parses a single message from the route manager. We allow multiple, newline terminated,
records in each message; it is required that the last record in the message be complete (we do not
@@ -256,7 +274,6 @@
char* tokens[128];
char wbuf[128];
int ntoks;
- int vfd = -1; // verbose file des if we have one
int vlevel = 0; // how chatty we should be 0== no nattering allowed
char* eptr;
int epfd = -1; // fd for epoll so we can multi-task
@@ -274,10 +291,7 @@
return NULL;
}
- if( (eptr = getenv( ENV_VERBOSE_FILE )) != NULL ) {
- vfd = open( eptr, O_RDONLY );
- vlevel = refresh_vlevel( vfd );
- }
+ vlevel = refresh_vlevel( 0 );
if( (eptr = getenv( ENV_RTREQ_FREA )) != NULL ) {
rt_req_freq = atoi( eptr );
@@ -357,7 +371,7 @@
msg = rmr_torcv_msg( pvt_cx, msg, 1000 );
if( time( NULL ) > blabber ) {
- vlevel = refresh_vlevel( vfd );
+ vlevel = refresh_vlevel( 0 );
blabber = time( NULL ) + count_delay; // set next time to blabber, then do so
if( blabber > bump_freq ) {
count_delay = 300;
@@ -372,7 +386,7 @@
}
}
- vlevel = refresh_vlevel( vfd ); // ensure it's fresh when we get a message
+ vlevel = refresh_vlevel( 0 ); // ensure it's fresh when we get a message
if( msg != NULL && msg->len > 0 ) {
rtc_parse_msg( ctx, pvt_cx, msg, vlevel, &flags );
@@ -456,7 +470,6 @@
int pbuf_size = 0; // number allocated in pbuf
int ntoks;
int raw_interface = 1; // rtg is using raw NNG/Nano not RMr to send updates
- int vfd = -1; // verbose file des if we have one
int vlevel = 0; // how chatty we should be 0== no nattering allowed
char* eptr;
int epfd = -1; // fd for epoll so we can multi-task
@@ -472,11 +485,7 @@
return NULL;
}
- if( (eptr = getenv( ENV_VERBOSE_FILE )) != NULL ) {
- vfd = open( eptr, O_RDONLY );
- vlevel = refresh_vlevel( vfd );
- }
-
+ vlevel = refresh_vlevel( 0 );
read_static_rt( ctx, vlevel ); // seed the route table if one provided
if( (port = getenv( ENV_RTG_PORT )) == NULL || ! *port ) { // port we need to open to listen for RTG connections
@@ -556,7 +565,7 @@
}
if( time( NULL ) > blabber ) {
- vlevel = refresh_vlevel( vfd );
+ vlevel = refresh_vlevel( 0 );
if( vlevel >= 0 ) { // allow it to be forced off with -n in verbose file
blabber = time( NULL ) + count_delay; // set next time to blabber, then do so
if( blabber > bump_freq ) {
@@ -567,7 +576,7 @@
}
}
- vlevel = refresh_vlevel( vfd ); // ensure it's fresh when we get a message
+ vlevel = refresh_vlevel( 0 ); // ensure it's fresh when we get a message
if( msg != NULL && msg->len > 0 ) {
payload = msg->payload;
diff --git a/src/rmr/si/src/rmr_si.c b/src/rmr/si/src/rmr_si.c
index 625a58d..9018fb1 100644
--- a/src/rmr/si/src/rmr_si.c
+++ b/src/rmr/si/src/rmr_si.c
@@ -736,11 +736,11 @@
}
- if( (interface = getenv( ENV_BIND_IF )) == NULL ) {
+ if( (interface = getenv( ENV_BIND_IF )) == NULL ) { // if specific interface not defined, listen on all
interface = "0.0.0.0";
}
- snprintf( bind_info, sizeof( bind_info ), "%s:%s", interface, port ); // FIXME -- si only supports 0.0.0.0 by default
+ snprintf( bind_info, sizeof( bind_info ), "%s:%s", interface, port );
if( (state = SIlistener( ctx->si_ctx, TCP_DEVICE, bind_info )) < 0 ) {
rmr_vlog( RMR_VL_CRIT, "rmr_init: unable to start si listener for %s: %s\n", bind_info, strerror( errno ) );
goto err;