Add millisecond resolution to log timestamps 72/5672/1
authorE. Scott Daniels <daniels@research.att.com>
Wed, 17 Feb 2021 20:01:58 +0000 (15:01 -0500)
committerE. Scott Daniels <daniels@research.att.com>
Wed, 17 Feb 2021 20:01:58 +0000 (15:01 -0500)
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

CHANGES_CORE.txt
CMakeLists.txt
src/rmr/common/src/logging.c
src/rmr/common/src/rtc_static.c
src/rmr/si/src/rmr_si.c

index e59da47..5be9139 100644 (file)
@@ -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)
index 5cd177e..be0e448 100644 (file)
@@ -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" )
index 56457f7..f87b65d 100644 (file)
@@ -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
index 8fe852d..2525342 100644 (file)
 
 // ------------------------------------------------------------------------------------------------
 
+/*
+       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 @@ 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;
index 625a58d..9018fb1 100644 (file)
@@ -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;