From c1c70b9063270159319be48bb091051da906b6d0 Mon Sep 17 00:00:00 2001 From: "E. Scott Daniels" Date: Wed, 17 Feb 2021 15:01:58 -0500 Subject: [PATCH] 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 Change-Id: I207150679370add11fcdeef381ff453b28e701db --- CHANGES_CORE.txt | 14 +++++- CMakeLists.txt | 4 +- src/rmr/common/src/logging.c | 33 +++++++++++++- src/rmr/common/src/rtc_static.c | 99 ++++++++++++++++++++++------------------- src/rmr/si/src/rmr_si.c | 4 +- 5 files changed, 102 insertions(+), 52 deletions(-) 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 @@ project( rmr LANGUAGES C ) 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 @@ -89,6 +89,23 @@ static int log_hrlogging = 1; static int log_pid = 0; 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. */ @@ -146,7 +163,7 @@ extern void rmr_vlog( int write_level, char* fmt, ... ) { } 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 @@ extern void rmr_vlog_force( int write_level, char* fmt, ... ) { 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 @@ extern void rmr_set_vlevel( int new_level ) { } } +#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 @@ -52,6 +52,52 @@ // ------------------------------------------------------------------------------------------------ +/* + 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. @@ -59,7 +105,6 @@ 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 @@ static void* rtc_file( void* vctx ) { 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 @@ static void* rtc( void* vctx ) { 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 @@ static void* rtc( void* vctx ) { 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 @@ static void* rtc( void* vctx ) { 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 @@ static void* rtc( void* vctx ) { } } - 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 @@ static void* raw_rtc( void* vctx ) { 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 @@ static void* raw_rtc( void* vctx ) { 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 @@ static void* raw_rtc( void* vctx ) { } 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 @@ static void* raw_rtc( void* vctx ) { } } - 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 @@ static void* init( char* uproto_port, int def_msg_size, int flags ) { } - 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; -- 2.16.6