src/rmr/common/src/logging.c

   1 // :vi sw=4 ts=4 noet:
   2 /*
   3 ==================================================================================
   4         Copyright (c) 2019-2020 Nokia
   5         Copyright (c) 2018-2020 AT&T Intellectual Property.
   6
   7    Licensed under the Apache License, Version 2.0 (the "License");
   8    you may not use this file except in compliance with the License.
   9    You may obtain a copy of the License at
  10
  11            http://www.apache.org/licenses/LICENSE-2.0
  12
  13    Unless required by applicable law or agreed to in writing, software
  14    distributed under the License is distributed on an "AS IS" BASIS,
  15    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  16    See the License for the specific language governing permissions and
  17    limitations under the License.
  18 ==================================================================================
  19 */
  20 /*
  21         Mnemonic:       logging.c
  22         Abstract:       Implements a common logging interface.
  23
  24                                 Some thoughts and theory....
  25                                 Libraries should write human readable messages to standard error
  26                                 when errors, warnings, or general information messages are called
  27                                 for.  These messages should NEVER be written to standard output,
  28                                 and should never be mixed with an application's log messages which
  29                                 are assumed to contain potentially sensitive information, such as
  30                                 user names, and should not be written to standard error.
  31
  32                                 For libraries such as RMR, where speed and latency are absolutely
  33                                 critical, logging should only be done from non-critical path code,
  34                                 or when an error has already compromised the ability to be performant.
  35                                 Thus, it is expected that most calls to the functions here are of
  36                                 the form:
  37                                         if( DEBUG ) rmr_logger( vlevel, fmt, parms);
  38
  39                                 such that the call to rmr_logger() is removed from the code unless
  40                                 compiled with the DEBUG flag set.  Code such as
  41                                         if( vlevel >= WARNING ) {
  42                                                 rmr_logger( fmt, parms )
  43                                         }
  44
  45                                 is unacceptable because it adds unnecessary checking for the current
  46                                 verbosity level setting in line.
  47
  48
  49                                 With respect to formatting messages written to stderr: they should NOT
  50                                 be written with json, or anyother form of mark up.  Idealy, they should
  51                                 use a syntax similar to system log:
  52                                         <timestamp> <pid> <situation> <message>
  53
  54                                 where timestamp is UNIX time, pid is the process id, situation is error,
  55                                 warning, etc, and message is obviously the text.
  56
  57                                 Thus, the default messages geneated are "plain."  Because some might feel
  58                                 that messages need to be formatted, the code here provides for the gross
  59                                 encapsulation of standard error text into json (best wishes for the poor
  60                                 sap who is left having to read the output on some dark and stormy night).
  61                                 To enable this, the environment veriable RMR_HRLOG=0 must be set to
  62                                 turn off human readable logs.
  63
  64         Author:         E. Scott Daniels
  65         Date:           27 January 2020
  66 */
  67
  68 #ifndef _logger_static_c
  69 #define _logger_static_c
  70
  71 #include <unistd.h>
  72 #include <stdarg.h>
  73 #include <stdio.h>
  74 #include <stdlib.h>
  75 #include <strings.h>
  76 #include <errno.h>
  77 #include <string.h>
  78 #include <stdint.h>
  79 #include <time.h>
  80
  81
  82 #include <rmr.h>
  83 #include <rmr_agnostic.h>
  84 #include <rmr_logging.h>
  85
  86 static int log_initialised = 0;
  87 static int log_vlevel = RMR_VL_ERR;
  88 static int log_hrlogging = 1;
  89 static int log_pid = 0;
  90 static char* log_situations[RMR_VL_DEBUG+1];
  91
  92 /*
  93         Return the current unix timestamp as milliseconds since the epoch.
  94         If time() returns 515300400, this function will add three didgets which
  95         represent the milliseconds:  515300400123 (515300400.123).
  96 */
  97 extern long long mstime( ) {
  98         struct timespec now;
  99         long long rv = 0;
 100
 101         if( clock_gettime( CLOCK_REALTIME, &now ) ) {
 102                 return rv;
 103         }
 104
 105         rv = ((long long) now.tv_sec * 1000) + ( (long long) now.tv_nsec/1000000 );
 106         return rv;
 107 }
 108
 109 /*
 110         Initialise logging. Returns the current log level.
 111 */
 112 extern int rmr_vlog_init( ) {
 113         char*   data;
 114
 115         if( (data = getenv( ENV_LOG_HR )) != NULL ) {
 116                 log_hrlogging = atoi( data );
 117         }
 118
 119         if( (data = getenv( ENV_LOG_VLEVEL )) != NULL ) {
 120                 log_vlevel = atoi( data );
 121                 if( log_vlevel < -1 ) {                                                 // allow housekeeping stats to be squelched with -1
 122                         log_vlevel = -1;
 123                 } else {
 124                         if( log_vlevel > RMR_VL_DEBUG ) {
 125                                 log_vlevel = RMR_VL_DEBUG;
 126                         }
 127                 }
 128         }
 129
 130         log_pid = getpid();
 131         log_situations[RMR_VL_DEBUG] = LOG_DEBUG;
 132         log_situations[RMR_VL_INFO] = LOG_INFO;
 133         log_situations[RMR_VL_WARN] = LOG_WARN;
 134         log_situations[RMR_VL_ERR] = LOG_ERROR;
 135         log_situations[RMR_VL_CRIT] = LOG_CRIT;
 136
 137         log_initialised = 1;
 138
 139         return log_vlevel;
 140 }
 141
 142 /*
 143         Write a variable message formatted in the same vein as *printf.
 144         We add a header to each log message with time, pid and message
 145         situation (error, warning, etc.).
 146 */
 147 extern void rmr_vlog( int write_level, char* fmt, ... ) {
 148         va_list argp;           // first arg in our parms which is variable
 149         char    msg[4096];
 150         int             hlen;
 151         char*   body;           // pointer into msg, past header
 152
 153         if( write_level > log_vlevel ) {                        // write too big, skip
 154                 return;
 155         }
 156
 157         if( ! log_initialised ) {
 158                 rmr_vlog_init();
 159         }
 160
 161         if( write_level > RMR_VL_DEBUG || write_level < 0 ) {
 162                 write_level = RMR_VL_DEBUG;
 163         }
 164
 165         memset( msg, 0, sizeof( msg ) );                                                                // logging is slow; this ensures 0 term if msg is too large
 166         hlen = snprintf( msg, sizeof( msg ), "%lld %d/RMR [%s] ", mstime( ), log_pid, log_situations[write_level] );
 167         if( hlen > sizeof( msg ) - 1024 ) {                                                             // should never happen, but be parinoid
 168                 return;
 169         }
 170         body = msg + hlen;
 171
 172         va_start( argp, fmt );          // suss out parm past fmt
 173
 174         vsnprintf( body, sizeof( msg ) - (hlen+2), fmt, argp );                 // add in user message formatting it along the way
 175         fprintf( stderr, "%s", msg );                                                                   // we grew from printfs so all existing msg have \n; assume there
 176
 177         va_end( argp );
 178 }
 179
 180 /*
 181         This ensures that the message is written regardless of the current log level
 182         setting. This allows for route table collection verbose levels to be taken
 183         into consideration separately from the err/warn/debug messages.  Component
 184         verbosity would be better and should be implemented.
 185 */
 186
 187 extern void rmr_vlog_force( int write_level, char* fmt, ... ) {
 188         va_list argp;           // first arg in our parms which is variable
 189         char    msg[4096];
 190         int             hlen;
 191         char*   body;           // pointer into msg, past header
 192
 193         if( ! log_initialised ) {
 194                 rmr_vlog_init();
 195         }
 196
 197         if( log_vlevel <= 0 ) {                 // can force if off completely to allow for total silience
 198                 return;
 199         }
 200
 201         if( write_level > RMR_VL_DEBUG || write_level < 0 ) {
 202                 write_level = RMR_VL_DEBUG;
 203         }
 204
 205         hlen = snprintf( msg, sizeof( msg ), "%lld %d/RMR [%s] ", mstime( ), log_pid, log_situations[write_level] );
 206         body = msg + hlen;
 207
 208         va_start( argp, fmt );          // suss out parm past fmt
 209
 210         vsnprintf( body, sizeof( msg ) - (hlen+2), fmt, argp );                 // add in user message formatting it along the way
 211         fprintf( stderr, "%s", msg );                                                                   // we grew from printfs so all existing msg have \n; assume there
 212
 213         va_end( argp );
 214 }
 215
 216 // -------------------- public functions that are needed -----------------
 217
 218 /*
 219         Allow user control to logging level control. Accepts a new log level
 220         from the user programme.  Messages which have a write level setting
 221         which is >= to the new level will be written.  Setting the new value
 222         to RMR_VL_OFF disables all logging (not advised).
 223 */
 224 extern void rmr_set_vlevel( int new_level ) {
 225         if( new_level >= 0 ) {
 226                 log_vlevel = new_level;
 227         }
 228 }
 229
 230 #ifdef QUICK_TEST
 231 /*
 232         Quick tests are some simple "pre" unit tests.
 233         Compile with:
 234                 gcc -DQUICK_TEST=1 logging.c
 235 */
 236 int main( ) {
 237         printf( "mstime=%lld   unix=%ld\n", mstime(), (long) time( NULL ) );
 238 }
 239 #endif
 240
 241
 242 #endif