From 918862475cf82f07bc68684aa7c2281af1bd1107 Mon Sep 17 00:00:00 2001 From: Melissa Elkadi Date: Tue, 25 Jan 2022 05:53:41 -0800 Subject: [PATCH] Removing log_minimal and adding new run-time logging opts --- common/utils/LOG/log.c | 123 ++++++++++++++++++++--------------------- common/utils/LOG/log.h | 43 +++++--------- 2 files changed, 72 insertions(+), 94 deletions(-) diff --git a/common/utils/LOG/log.c b/common/utils/LOG/log.c index 28134d6db1..0679e0b521 100644 --- a/common/utils/LOG/log.c +++ b/common/utils/LOG/log.c @@ -65,6 +65,7 @@ char logmem_filename[1024] = {0}; mapping log_level_names[] = { {"error", OAILOG_ERR}, {"warn", OAILOG_WARNING}, + {"analysis", OAILOG_ANALYSIS}, {"info", OAILOG_INFO}, {"debug", OAILOG_DEBUG}, {"trace", OAILOG_TRACE}, @@ -78,6 +79,7 @@ mapping log_options[] = { {"line_num", FLAG_FILE_LINE }, {"function", FLAG_FUNCT}, {"time", FLAG_TIME}, + {"thread_id", FLAG_THREAD_ID}, {NULL,-1} }; @@ -501,6 +503,7 @@ int logInit (void) return 0; } +#include static inline int log_header(log_component_t *c, char *log_buffer, int buffsize, @@ -514,32 +517,43 @@ static inline int log_header(log_component_t *c, char threadname[64]; if (flag & FLAG_THREAD ) { threadname[0]='{'; - if ( pthread_getname_np(pthread_self(), threadname+1,61) != 0) + if (pthread_getname_np(pthread_self(), threadname + 1, sizeof(threadname) - 3) != 0) strcpy(threadname+1, "?thread?"); - strcat(threadname,"}"); + strcat(threadname,"} "); } else { threadname[0]=0; } - + char l[32]; if (flag & FLAG_FILE_LINE && flag & FLAG_FUNCT ) - snprintf(l, sizeof l," (%s:%d) ", func, line); + snprintf(l, sizeof l, "(%s:%d) ", func, line); else if (flag & FLAG_FILE_LINE) - sprintf(l," (%d) ", line); + snprintf(l, sizeof l, "(%d) ", line); else - l[0]=0; + l[0] = 0; char timeString[32]; if ( flag & FLAG_TIME ) { struct timespec t; - clock_gettime(CLOCK_MONOTONIC, &t); - snprintf(timeString, sizeof t,"%05.3f",t.tv_sec+t.tv_nsec/1.0e9); + if (clock_gettime(CLOCK_MONOTONIC, &t) == -1) + abort(); + snprintf(timeString, sizeof(timeString), "%lu.%06lu ", + t.tv_sec, + t.tv_nsec / 1000); } else { - timeString[0]=0; + timeString[0] = 0; } - return snprintf(log_buffer, buffsize, "%s%s[%s]%c%s %s ", + + char threadIdString[32]; + if (flag & FLAG_THREAD_ID) { + snprintf(threadIdString, sizeof(threadIdString), "%08lx ", syscall(__NR_gettid)); + } else { + threadIdString[0] = 0; + } + return snprintf(log_buffer, buffsize, "%s%s%s[%s] %c %s%s", timeString, flag & FLAG_NOCOLOR ? "" : log_level_highlight_start[level], + threadIdString, c->name, flag & FLAG_LEVEL ? g_log->level2string[level] : ' ', l, @@ -547,53 +561,6 @@ static inline int log_header(log_component_t *c, ); } -#if LOG_MINIMAL -#include -void logMinimal(int comp, int level, const char *format, ...) -{ - struct timespec ts; - if (clock_gettime(CLOCK_MONOTONIC, &ts) == -1) - abort(); - - char buf[MAX_LOG_TOTAL]; - int n = snprintf(buf, sizeof(buf), "%lu.%06lu %08lx [%s] %c ", - ts.tv_sec, - ts.tv_nsec / 1000, - syscall(__NR_gettid), - g_log->log_component[comp].name, - level); - if (n < 0 || n >= sizeof(buf)) - { - fprintf(stderr, "%s: n=%d\n", __func__, n); - return; - } - - va_list args; - va_start(args, format); - int m = vsnprintf(buf + n, sizeof(buf) - n, format, args); - va_end(args); - - if (m < 0) - { - fprintf(stderr, "%s: n=%d m=%d\n", __func__, n, m); - return; - } - - int len = n + m; - if (len > sizeof(buf) - 1) - { - len = sizeof(buf) - 1; - } - if (buf[len - 1] != '\n') - { - buf[len++] = '\n'; - } - - __attribute__((unused)) - int unused = write(STDOUT_FILENO, buf, len); -} -#endif // LOG_MINIMAL - void logRecord_mt(const char *file, const char *func, int line, @@ -864,7 +831,14 @@ void flush_mem_to_file(void) } } -char logmem_log_level[NUM_LOG_LEVEL]={'E','W','I','D','T'}; +const char logmem_log_level[NUM_LOG_LEVEL] = { + [OAILOG_ERR] = 'E', + [OAILOG_WARNING] = 'W', + [OAILOG_ANALYSIS] = 'A', + [OAILOG_INFO] = 'I', + [OAILOG_DEBUG] = 'D', + [OAILOG_TRACE] = 'T', +}; static void log_output_memory(log_component_t *c, const char *file, const char *func, int line, int comp, int level, const char* format,va_list args) { @@ -878,12 +852,32 @@ static void log_output_memory(log_component_t *c, const char *file, const char * char log_buffer[MAX_LOG_TOTAL]; // make sure that for log trace the extra info is only printed once, reset when the level changes - if (level < OAILOG_TRACE) - len += log_header(c, log_buffer, MAX_LOG_TOTAL, file, func, line, level); - len += vsnprintf(log_buffer+len, MAX_LOG_TOTAL-len, format, args); - if ( !((g_log->flag | c->flag) & FLAG_NOCOLOR) ) - len+=snprintf(log_buffer+len, MAX_LOG_TOTAL-len, "%s", log_level_highlight_end[level]); - + if (level < OAILOG_TRACE) { + int n = log_header(c, log_buffer+len, MAX_LOG_TOTAL, file, func, line, level); + if (n > 0) { + len += n; + if (len > MAX_LOG_TOTAL) { + len = MAX_LOG_TOTAL; + } + } + } + int n = vsnprintf(log_buffer+len, MAX_LOG_TOTAL-len, format, args); + if (n > 0) { + len += n; + if (len > MAX_LOG_TOTAL) { + len = MAX_LOG_TOTAL; + } + } + if ( !((g_log->flag | c->flag) & FLAG_NOCOLOR) ) { + int n = snprintf(log_buffer+len, MAX_LOG_TOTAL-len, "%s", log_level_highlight_end[level]); + if (n > 0) { + len += n; + if (len > MAX_LOG_TOTAL) { + len = MAX_LOG_TOTAL; + } + } + } + // OAI printf compatibility if(log_mem_flag==1){ if(log_mem_d[log_mem_side].enable_flag==1){ @@ -919,6 +913,7 @@ static void log_output_memory(log_component_t *c, const char *file, const char * } } }else{ + AssertFatal(len >= 0 && len <= MAX_LOG_TOTAL, "Bad len %d\n", len); if (write(fileno(c->stream), log_buffer, len)) {}; } } diff --git a/common/utils/LOG/log.h b/common/utils/LOG/log.h index 350337b61b..42e49747a1 100644 --- a/common/utils/LOG/log.h +++ b/common/utils/LOG/log.h @@ -90,11 +90,12 @@ extern "C" { # define OAILOG_DISABLE -1 /*!< \brief disable all LOG messages, cannot be used in LOG macros, use only in LOG module */ # define OAILOG_ERR 0 /*!< \brief critical error conditions, impact on "must have" functionalities */ # define OAILOG_WARNING 1 /*!< \brief warning conditions, shouldn't happen but doesn't impact "must have" functionalities */ -# define OAILOG_INFO 2 /*!< \brief informational messages most people don't need, shouldn't impact real-time behavior */ -# define OAILOG_DEBUG 3 /*!< \brief first level debug-level messages, for developers, may impact real-time behavior */ -# define OAILOG_TRACE 4 /*!< \brief second level debug-level messages, for developers, likely impact real-time behavior*/ +# define OAILOG_ANALYSIS 2 /*!< \brief informational messages most people don't need, shouldn't impact real-time behavior */ +# define OAILOG_INFO 3 /*!< \brief informational messages most people don't need, shouldn't impact real-time behavior */ +# define OAILOG_DEBUG 4 /*!< \brief first level debug-level messages, for developers, may impact real-time behavior */ +# define OAILOG_TRACE 5 /*!< \brief second level debug-level messages, for developers, likely impact real-time behavior*/ -#define NUM_LOG_LEVEL 5 /*!< \brief the number of message levels users have with LOG (OAILOG_DISABLE is not available to user as a level, so it is not included)*/ +#define NUM_LOG_LEVEL 6 /*!< \brief the number of message levels users have with LOG (OAILOG_DISABLE is not available to user as a level, so it is not included)*/ /* @}*/ @@ -127,6 +128,7 @@ extern "C" { #define FLAG_FUNCT 0x0020 #define FLAG_FILE_LINE 0x0040 #define FLAG_TIME 0x0100 +#define FLAG_THREAD_ID 0x0200 #define FLAG_INITIALIZED 0x8000 #define SET_LOG_OPTION(O) g_log->flag = (g_log->flag | O) @@ -408,32 +410,14 @@ int32_t write_file_matlab(const char *fname, const char *vname, void *data, int // debugging macros #define LOG_F LOG_I /* because LOG_F was originaly to dump a message or buffer but is also used as a regular level...., to dump use LOG_DUMPMSG */ -#if LOG_MINIMAL - - void logMinimal(int component, int level, const char *format, ...) __attribute__((format(printf, 3, 4))); -# define LOG_E(COMPONENT, ...) do if (1) logMinimal(COMPONENT, 'E', __VA_ARGS__); while (0) -# define LOG_W(COMPONENT, ...) do if (1) logMinimal(COMPONENT, 'W', __VA_ARGS__); while (0) -# define LOG_A(COMPONENT, ...) do if (1) logMinimal(COMPONENT, 'A', __VA_ARGS__); while (0) /* logs intended for analysis */ -# define LOG_I(COMPONENT, ...) do if (1) logMinimal(COMPONENT, 'I', __VA_ARGS__); while (0) -# define LOG_D(COMPONENT, ...) do if (0) logMinimal(COMPONENT, 'D', __VA_ARGS__); while (0) -# define LOG_T(COMPONENT, ...) do if (0) logMinimal(COMPONENT, 'T', __VA_ARGS__); while (0) - -# define LOG_M(FILE, VECTOR, DATA, LEN, DEC, FORMAT) ((void) 0) -# define LOG_DUMPFLAG(D) 0 -# define LOG_DEBUGFLAG(D) 0 -# define LOG_DUMPMSG(C, B, S, X...) ((void) 0) -# define VLOG(C, L, F, ARGS) ((void) 0) - -#else // LOG_MINIMAL - # if T_TRACER /* per component, level dependent macros */ -# define LOG_E(c, x...) do { T(T_LEGACY_ ## c ## _ERROR, T_PRINTF(x)) ; if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_ERR ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_ERR, x) ;} } while (0) -# define LOG_W(c, x...) do { T(T_LEGACY_ ## c ## _WARNING, T_PRINTF(x)); if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_WARNING) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_WARNING, x);} } while (0) -# define LOG_A LOG_I -# define LOG_I(c, x...) do { T(T_LEGACY_ ## c ## _INFO, T_PRINTF(x)) ; if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_INFO ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_INFO, x) ;} } while (0) -# define LOG_D(c, x...) do { T(T_LEGACY_ ## c ## _DEBUG, T_PRINTF(x)) ; if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_DEBUG ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_DEBUG, x) ;} } while (0) -# define LOG_T(c, x...) do { T(T_LEGACY_ ## c ## _TRACE, T_PRINTF(x)) ; if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_TRACE ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_TRACE, x) ;} } while (0) +# define LOG_E(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_ERR ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_ERR, x) ;} else { T(T_LEGACY_ ## c ## _ERROR, T_PRINTF(x)) ;}} while (0) +# define LOG_W(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_WARNING) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_WARNING, x) ;} else { T(T_LEGACY_ ## c ## _WARNING, T_PRINTF(x)) ;}} while (0) +# define LOG_A(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_ANALYSIS) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_ANALYSIS, x) ;} else { T(T_LEGACY_ ## c ## _INFO, T_PRINTF(x)) ;}} while (0) +# define LOG_I(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_INFO ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_INFO, x) ;} else { T(T_LEGACY_ ## c ## _INFO, T_PRINTF(x)) ;}} while (0) +# define LOG_D(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_DEBUG ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_DEBUG, x) ;} else { T(T_LEGACY_ ## c ## _DEBUG, T_PRINTF(x)) ;}} while (0) +# define LOG_T(c, x...) do { if (T_stdout) { if( g_log->log_component[c].level >= OAILOG_TRACE ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_TRACE, x) ;} else { T(T_LEGACY_ ## c ## _TRACE, T_PRINTF(x)) ;}} while (0) # define VLOG(c,l, f, args) do { if (T_stdout) { if( g_log->log_component[c].level >= l ) vlogRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, l, f, args) ;} } while (0) /* macro used to dump a buffer or a message as in openair2/RRC/LTE/RRC_eNB.c, replaces LOG_F macro */ # define LOG_DUMPMSG(c, f, b, s, x...) do { if(g_log->dump_mask & f) log_dump(c, b, s, LOG_DUMP_CHAR, x) ;} while (0) /* */ @@ -449,8 +433,8 @@ int32_t write_file_matlab(const char *fname, const char *vname, void *data, int # define LOG_E(c, x...) do { if( g_log->log_component[c].level >= OAILOG_ERR ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_ERR, x) ;} while (0) # define LOG_W(c, x...) do { if( g_log->log_component[c].level >= OAILOG_WARNING) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_WARNING, x) ;} while (0) +# define LOG_A(c, x...) do { if( g_log->log_component[c].level >= OAILOG_ANALYSIS) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_ANALYSIS, x);} while (0) # define LOG_I(c, x...) do { if( g_log->log_component[c].level >= OAILOG_INFO ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_INFO, x) ;} while (0) -# define LOG_A LOG_I # define LOG_D(c, x...) do { if( g_log->log_component[c].level >= OAILOG_DEBUG ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_DEBUG, x) ;} while (0) # define LOG_T(c, x...) do { if( g_log->log_component[c].level >= OAILOG_TRACE ) logRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, OAILOG_TRACE, x) ;} while (0) # define VLOG(c,l, f, args) do { if( g_log->log_component[c].level >= l ) vlogRecord_mt(__FILE__, __FUNCTION__, __LINE__,c, l, f, args) ; } while (0) @@ -464,7 +448,6 @@ int32_t write_file_matlab(const char *fname, const char *vname, void *data, int # define LOG_VAR(A,B) A B # define T_ACTIVE(a) (0) # endif /* T_TRACER */ -#endif // LOG_MINIMAL /* avoid warnings for variables only used in LOG macro's but set outside debug section */ #define GCC_NOTUSED __attribute__((unused))