From e5c214ab8cad21bd6428780cd2a4a61bc5b7fe04 Mon Sep 17 00:00:00 2001 From: Cedric Roux <cedric.roux@eurecom.fr> Date: Fri, 29 May 2015 14:50:04 +0000 Subject: [PATCH] fixing logs - components' buffers are global and various threads doing log accesssed them at the same time. The log function now uses a local buffer instead. git-svn-id: http://svn.eurecom.fr/openair4G/trunk@7500 818b1a75-f10b-46b9-bf7c-635c3b92a50f --- openair2/UTIL/LOG/log.c | 287 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 287 insertions(+) diff --git a/openair2/UTIL/LOG/log.c b/openair2/UTIL/LOG/log.c index 429dce8587..1ae3b720f2 100755 --- a/openair2/UTIL/LOG/log.c +++ b/openair2/UTIL/LOG/log.c @@ -674,6 +674,12 @@ void *log_thread_function(void *list) } #endif +#if 0 +/* This function does not work. When multiple threads call it at the same time + * for the same component, both threads end up using the same buffer. + * The output is the completely messed up/wrong. + * Kept in case the fix below is not correct or acceptable. + */ //log record, format, and print: executed in the main thread (mt) void logRecord_mt(const char *file, const char *func, int line, int comp, int level, const char *format, ...) @@ -934,6 +940,287 @@ void logRecord_mt(const char *file, const char *func, int line, int comp, itti_send_msg_to_task(TASK_UNKNOWN, INSTANCE_DEFAULT, message_p); } +#endif + + VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD, + VCD_FUNCTION_OUT); +} +#endif /* #if 0 */ + +//log record, format, and print: executed in the main thread (mt) +void logRecord_mt(const char *file, const char *func, int line, int comp, + int level, const char *format, ...) +{ + int len = 0; + va_list args; + log_component_t *c; + char *log_start; + char *log_end; + /* The main difference with the version above is the use of this local log_buffer. + * The other difference is the return value of snprintf which was not used + * correctly. It was not a big problem because in practice MAX_LOG_TOTAL is + * big enough so that the buffer is never full. + */ + char log_buffer[MAX_LOG_TOTAL]; + + c = &g_log->log_component[comp]; + + // do not apply filtering for LOG_F + // only log messages which are enabled and are below the global log level and component's level threshold + if ((level != LOG_FILE) && ((level > c->level) || (level > g_log->level))) { + /* if ((level != LOG_FILE) && + ((level > c->level) || + (level > g_log->level) || + ( c->level > g_log->level))) { + */ + return; + } + + VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD, + VCD_FUNCTION_IN); + + va_start(args, format); + + // adjust syslog level for TRACE messages + if (g_log->syslog) { + if (g_log->level > LOG_DEBUG) { + g_log->level = LOG_DEBUG; + } + } + + // make sure that for log trace the extra info is only printed once, reset when the level changes + if ((level == LOG_FILE) || (c->flag == LOG_NONE) || (level == LOG_TRACE)) { + log_start = log_buffer; + len = vsnprintf(log_buffer, MAX_LOG_TOTAL, format, args); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + log_end = log_buffer + len; + } else { + if ( (g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR) ) { + len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "%s", + log_level_highlight_start[level]); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + } + + log_start = log_buffer + len; + + if ( (g_log->flag & FLAG_COMP) || (c->flag & FLAG_COMP) ) { + len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "[%s]", + g_log->log_component[comp].name); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + } + + if ( (g_log->flag & FLAG_LEVEL) || (c->flag & FLAG_LEVEL) ) { + len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "[%s]", + g_log->level2string[level]); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + } + + if ( (g_log->flag & FLAG_FUNCT) || (c->flag & FLAG_FUNCT) ) { + len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "[%s] ", + func); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + } + + if ( (g_log->flag & FLAG_FILE_LINE) || (c->flag & FLAG_FILE_LINE) ) { + len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "[%s:%d]", + file, line); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + } + + len += vsnprintf(&log_buffer[len], MAX_LOG_TOTAL - len, format, args); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + log_end = log_buffer + len; + + if ( (g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR) ) { + len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "%s", + log_level_highlight_end[level]); + if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL; + } + } + + va_end(args); + + // OAI printf compatibility + if ((g_log->onlinelog == 1) && (level != LOG_FILE)) +#ifdef RTAI + if (len > MAX_LOG_TOTAL) { + rt_printk ("[OPENAIR] FIFO_PRINTF WROTE OUTSIDE ITS MEMORY BOUNDARY : ERRORS WILL OCCUR\n"); + } + + if (len > 0) { + rtf_put (FIFO_PRINTF_NO, log_buffer, len); + } + +#else + fwrite(log_buffer, len, 1, stdout); +#endif + +#ifndef RTAI + + if (g_log->syslog) { + syslog(g_log->level, "%s", log_buffer); + } + + if (g_log->filelog) { + if (write(gfd, log_buffer, len) < len) { + // TODO assert ? + } + } + + if ((g_log->log_component[comp].filelog) && (level == LOG_FILE)) { + if (write(g_log->log_component[comp].fd, log_buffer, len) < len) { + // TODO assert ? + } + } + +#else + + // online print messges + if ((g_log->log_component[comp].filelog) && (level == LOG_FILE)) { + printf(log_buffer); + } + +#endif + +#if defined(ENABLE_ITTI) + + if (level <= LOG_DEBUG) { + task_id_t origin_task_id = TASK_UNKNOWN; + MessagesIds messages_id; + MessageDef *message_p; + size_t message_string_size; + char *message_msg_p; + + message_string_size = log_end - log_start; + +#if !defined(DISABLE_ITTI_DETECT_SUB_TASK_ID) + + /* Try to identify sub task ID from log information (comp, log_instance_type) */ + switch (comp) { + case PHY: + switch (log_instance_type) { + case LOG_INSTANCE_ENB: + origin_task_id = TASK_PHY_ENB; + break; + + case LOG_INSTANCE_UE: + origin_task_id = TASK_PHY_UE; + break; + + default: + break; + } + + break; + + case MAC: + switch (log_instance_type) { + case LOG_INSTANCE_ENB: + origin_task_id = TASK_MAC_ENB; + break; + + case LOG_INSTANCE_UE: + origin_task_id = TASK_MAC_UE; + + default: + break; + } + + break; + + case RLC: + switch (log_instance_type) { + case LOG_INSTANCE_ENB: + origin_task_id = TASK_RLC_ENB; + break; + + case LOG_INSTANCE_UE: + origin_task_id = TASK_RLC_UE; + + default: + break; + } + + break; + + case PDCP: + switch (log_instance_type) { + case LOG_INSTANCE_ENB: + origin_task_id = TASK_PDCP_ENB; + break; + + case LOG_INSTANCE_UE: + origin_task_id = TASK_PDCP_UE; + + default: + break; + } + + break; + + default: + break; + } + +#endif + + switch (level) { + case LOG_EMERG: + case LOG_ALERT: + case LOG_CRIT: + case LOG_ERR: + messages_id = ERROR_LOG; + break; + + case LOG_WARNING: + messages_id = WARNING_LOG; + break; + + case LOG_NOTICE: + messages_id = NOTICE_LOG; + break; + + case LOG_INFO: + messages_id = INFO_LOG; + break; + + default: + messages_id = DEBUG_LOG; + break; + } + + message_p = itti_alloc_new_message_sized(origin_task_id, messages_id, message_string_size); + + switch (level) { + case LOG_EMERG: + case LOG_ALERT: + case LOG_CRIT: + case LOG_ERR: + message_msg_p = (char *) &message_p->ittiMsg.error_log; + break; + + case LOG_WARNING: + message_msg_p = (char *) &message_p->ittiMsg.warning_log; + break; + + case LOG_NOTICE: + message_msg_p = (char *) &message_p->ittiMsg.notice_log; + break; + + case LOG_INFO: + message_msg_p = (char *) &message_p->ittiMsg.info_log; + break; + + default: + message_msg_p = (char *) &message_p->ittiMsg.debug_log; + break; + } + + memcpy(message_msg_p, log_start, message_string_size); + + itti_send_msg_to_task(TASK_UNKNOWN, INSTANCE_DEFAULT, message_p); + } + #endif VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD, -- 2.26.2