/******************************************************************************* OpenAirInterface Copyright(c) 1999 - 2014 Eurecom OpenAirInterface is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, either version 3 of the License, or (at your option) any later version. OpenAirInterface is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with OpenAirInterface.The full GNU General Public License is included in this distribution in the file called "COPYING". If not, see . Contact Information OpenAirInterface Admin: openair_admin@eurecom.fr OpenAirInterface Tech : openair_tech@eurecom.fr OpenAirInterface Dev : openair4g-devel@lists.eurecom.fr Address : Eurecom, Campus SophiaTech, 450 Route des Chappes, CS 50193 - 06904 Biot Sophia Antipolis cedex, FRANCE *******************************************************************************/ /*! \file log.c * \brief log implementaion * \author Navid Nikaein * \date 2009 - 2014 * \version 0.5 * @ingroup util */ //#define LOG_TEST 1 #define COMPONENT_LOG #define COMPONENT_LOG_IF #include "log.h" #include "vcd_signal_dumper.h" #include "assertions.h" #if defined(ENABLE_ITTI) # include "intertask_interface.h" #endif #ifdef USER_MODE # include # include #endif #ifdef RTAI # include # include # define FIFO_PRINTF_MAX_STRING_SIZE 1000 # define FIFO_PRINTF_NO 62 # define FIFO_PRINTF_SIZE 65536 #endif // main log variables log_t *g_log; mapping log_level_names[] = { {"emerg", LOG_EMERG}, {"alert", LOG_ALERT}, {"crit", LOG_CRIT}, {"error", LOG_ERR}, {"warn", LOG_WARNING}, {"notice", LOG_NOTICE}, {"info", LOG_INFO}, {"debug", LOG_DEBUG}, {"file", LOG_FILE}, {"trace", LOG_TRACE}, {NULL, -1} }; mapping log_verbosity_names[] = { {"none", 0x0}, {"low", 0x5}, {"medium", 0x15}, {"high", 0x35}, {"full", 0x75}, {NULL, -1} }; // vars for the log thread LOG_params log_list[2000]; int log_list_tail = 0; int log_list_nb_elements = 0; pthread_mutex_t log_lock; pthread_cond_t log_notify; #if !defined(LOG_NO_THREAD) int log_list_head = 0; int log_shutdown; #endif #ifndef RTAI static int gfd; #endif static char *log_level_highlight_start[] = {LOG_RED, LOG_RED, LOG_RED, LOG_RED, LOG_ORANGE, LOG_BLUE, "", ""}; /*!< \brief Optional start-format strings for highlighting */ static char *log_level_highlight_end[] = {LOG_RESET, LOG_RESET, LOG_RESET, LOG_RESET, LOG_RESET,LOG_RESET, "",""}; /*!< \brief Optional end-format strings for highlighting */ #if defined(ENABLE_ITTI) static log_instance_type_t log_instance_type; #endif int logInit (void) { #ifdef USER_MODE #ifndef RTAI int i; #endif g_log = calloc(1, sizeof(log_t)); #else g_log = kmalloc(sizeof(log_t), GFP_KERNEL); #endif if (g_log == NULL) { #ifdef USER_MODE perror ("cannot allocated memory for log generation module \n"); exit(EXIT_FAILURE); #else printk("cannot allocated memory for log generation module \n"); return(-1); #endif } #if ! defined(CN_BUILD) g_log->log_component[PHY].name = "PHY"; g_log->log_component[PHY].level = LOG_EMERG; g_log->log_component[PHY].flag = LOG_MED; g_log->log_component[PHY].interval = 1; g_log->log_component[PHY].fd = 0; g_log->log_component[PHY].filelog = 0; g_log->log_component[PHY].filelog_name = "/tmp/phy.log"; g_log->log_component[MAC].name = "MAC"; g_log->log_component[MAC].level = LOG_EMERG; g_log->log_component[MAC].flag = LOG_MED; g_log->log_component[MAC].interval = 1; g_log->log_component[MAC].fd = 0; g_log->log_component[MAC].filelog = 0; g_log->log_component[MAC].filelog_name = "/tmp/mac.log"; g_log->log_component[OPT].name = "OPT"; g_log->log_component[OPT].level = LOG_EMERG; g_log->log_component[OPT].flag = LOG_MED; g_log->log_component[OPT].interval = 1; g_log->log_component[OPT].fd = 0; g_log->log_component[OPT].filelog = 0; g_log->log_component[OPT].filelog_name = ""; g_log->log_component[RLC].name = "RLC"; g_log->log_component[RLC].level = LOG_INFO; g_log->log_component[RLC].flag = LOG_MED; g_log->log_component[RLC].interval = 1; g_log->log_component[RLC].fd = 0; g_log->log_component[RLC].filelog = 0; g_log->log_component[RLC].filelog_name = "/tmp/rlc.log"; g_log->log_component[PDCP].name = "PDCP"; g_log->log_component[PDCP].level = LOG_INFO; g_log->log_component[PDCP].flag = LOG_MED; g_log->log_component[PDCP].interval = 1; g_log->log_component[PDCP].fd = 0; g_log->log_component[PDCP].filelog = 0; g_log->log_component[PDCP].filelog_name = "/tmp/pdcp.log"; g_log->log_component[RRC].name = "RRC"; g_log->log_component[RRC].level = LOG_TRACE; g_log->log_component[RRC].flag = LOG_MED; g_log->log_component[RRC].interval = 1; g_log->log_component[RRC].fd = 0; g_log->log_component[RRC].filelog = 0; g_log->log_component[RRC].filelog_name = "/tmp/rrc.log"; g_log->log_component[EMU].name = "EMU"; g_log->log_component[EMU].level = LOG_EMERG; g_log->log_component[EMU].flag = LOG_MED; g_log->log_component[EMU].interval = 1; g_log->log_component[EMU].fd = 0; g_log->log_component[EMU].filelog = 0; g_log->log_component[EMU].filelog_name = ""; g_log->log_component[OMG].name = "OMG"; g_log->log_component[OMG].level = LOG_EMERG; g_log->log_component[OMG].flag = LOG_MED; g_log->log_component[OMG].interval = 1; g_log->log_component[OMG].fd = 0; g_log->log_component[OMG].filelog = 0; g_log->log_component[OMG].filelog_name = "/tmp/omg.csv"; g_log->log_component[OTG].name = "OTG"; g_log->log_component[OTG].level = LOG_EMERG; g_log->log_component[OTG].flag = LOG_MED; g_log->log_component[OTG].interval = 1; g_log->log_component[OTG].fd = 0; g_log->log_component[OTG].filelog = 0; g_log->log_component[OTG].filelog_name = "/tmp/otg.log"; g_log->log_component[OTG_LATENCY].name = "OTG_LATENCY"; g_log->log_component[OTG_LATENCY].level = LOG_EMERG; g_log->log_component[OTG_LATENCY].flag = LOG_MED; g_log->log_component[OTG_LATENCY].interval = 1; g_log->log_component[OTG_LATENCY].fd = 0; g_log->log_component[OTG_LATENCY].filelog = 0; g_log->log_component[OTG_LATENCY].filelog_name = "/tmp/otg_latency.dat"; g_log->log_component[OTG_LATENCY_BG].name = "OTG_LATENCY_BG"; g_log->log_component[OTG_LATENCY_BG].level = LOG_EMERG; g_log->log_component[OTG_LATENCY_BG].flag = LOG_MED; g_log->log_component[OTG_LATENCY_BG].interval = 1; g_log->log_component[OTG_LATENCY_BG].fd = 0; g_log->log_component[OTG_LATENCY_BG].filelog = 0; g_log->log_component[OTG_LATENCY_BG].filelog_name = "/tmp/otg_latency_bg.dat"; g_log->log_component[OTG_GP].name = "OTG_GP"; g_log->log_component[OTG_GP].level = LOG_EMERG; g_log->log_component[OTG_GP].flag = LOG_MED; g_log->log_component[OTG_GP].interval = 1; g_log->log_component[OTG_GP].fd = 0; g_log->log_component[OTG_GP].filelog = 0; g_log->log_component[OTG_GP].filelog_name = "/tmp/otg_goodput.dat"; g_log->log_component[OTG_GP_BG].name = "OTG_GP_BG"; g_log->log_component[OTG_GP_BG].level = LOG_EMERG; g_log->log_component[OTG_GP_BG].flag = LOG_MED; g_log->log_component[OTG_GP_BG].interval = 1; g_log->log_component[OTG_GP_BG].fd = 0; g_log->log_component[OTG_GP_BG].filelog = 0; g_log->log_component[OTG_GP_BG].filelog_name = "/tmp/otg_goodput_bg.dat"; g_log->log_component[OTG_JITTER].name = "OTG_JITTER"; g_log->log_component[OTG_JITTER].level = LOG_EMERG; g_log->log_component[OTG_JITTER].flag = LOG_MED; g_log->log_component[OTG_JITTER].interval = 1; g_log->log_component[OTG_JITTER].fd = 0; g_log->log_component[OTG_JITTER].filelog = 0; g_log->log_component[OTG_JITTER].filelog_name = "/tmp/otg_jitter.dat"; g_log->log_component[OCG].name = "OCG"; g_log->log_component[OCG].level = LOG_EMERG; g_log->log_component[OCG].flag = LOG_MED; g_log->log_component[OCG].interval = 1; g_log->log_component[OCG].fd = 0; g_log->log_component[OCG].filelog = 0; g_log->log_component[OCG].filelog_name = ""; g_log->log_component[PERF].name = "PERF"; g_log->log_component[PERF].level = LOG_EMERG; g_log->log_component[PERF].flag = LOG_MED; g_log->log_component[PERF].interval = 1; g_log->log_component[PERF].fd = 0; g_log->log_component[PERF].filelog = 0; g_log->log_component[PERF].filelog_name = ""; g_log->log_component[OIP].name = "OIP"; g_log->log_component[OIP].level = LOG_EMERG; g_log->log_component[OIP].flag = LOG_MED; g_log->log_component[OIP].interval = 1; g_log->log_component[OIP].fd = 0; g_log->log_component[OIP].filelog = 0; g_log->log_component[OIP].filelog_name = ""; g_log->log_component[CLI].name = "CLI"; g_log->log_component[CLI].level = LOG_EMERG; g_log->log_component[CLI].flag = LOG_MED; g_log->log_component[CLI].interval = 1; g_log->log_component[CLI].fd = 0; g_log->log_component[CLI].filelog = 0; g_log->log_component[CLI].filelog_name = ""; g_log->log_component[MSC].name = "MSC"; g_log->log_component[MSC].level = LOG_EMERG; g_log->log_component[MSC].flag = LOG_MED; g_log->log_component[MSC].interval = 1; g_log->log_component[MSC].fd = 0; g_log->log_component[MSC].filelog = 0; g_log->log_component[MSC].filelog_name = "/tmp/msc.log"; g_log->log_component[OCM].name = "OCM"; g_log->log_component[OCM].level = LOG_EMERG; g_log->log_component[OCM].flag = LOG_MED; g_log->log_component[OCM].interval = 1; g_log->log_component[OCM].fd = 0; g_log->log_component[OCM].filelog = 0; g_log->log_component[OCM].filelog_name = "/tmp/ocm.log"; g_log->log_component[HW].name = "HW"; g_log->log_component[HW].level = LOG_EMERG; g_log->log_component[HW].flag = LOG_MED; g_log->log_component[HW].interval = 1; g_log->log_component[HW].fd = 0; g_log->log_component[HW].filelog = 0; g_log->log_component[HW].filelog_name = ""; g_log->log_component[OSA].name = "OSA"; g_log->log_component[OSA].level = LOG_EMERG; g_log->log_component[OSA].flag = LOG_MED; g_log->log_component[OSA].interval = 1; g_log->log_component[OSA].fd = 0; g_log->log_component[OSA].filelog = 0; g_log->log_component[OSA].filelog_name = ""; g_log->log_component[RAL_ENB].name = "eRAL"; g_log->log_component[RAL_ENB].level = LOG_EMERG; g_log->log_component[RAL_ENB].flag = LOG_MED; g_log->log_component[RAL_ENB].interval = 1; g_log->log_component[RAL_ENB].fd = 0; g_log->log_component[RAL_ENB].filelog = 0; g_log->log_component[RAL_ENB].filelog_name = ""; g_log->log_component[RAL_UE].name = "mRAL"; g_log->log_component[RAL_UE].level = LOG_EMERG; g_log->log_component[RAL_UE].flag = LOG_MED; g_log->log_component[RAL_UE].interval = 1; g_log->log_component[RAL_UE].fd = 0; g_log->log_component[RAL_UE].filelog = 0; g_log->log_component[RAL_UE].filelog_name = ""; g_log->log_component[ENB_APP].name = "ENB_APP"; g_log->log_component[ENB_APP].level = LOG_EMERG; g_log->log_component[ENB_APP].flag = LOG_MED; g_log->log_component[ENB_APP].interval = 1; g_log->log_component[ENB_APP].fd = 0; g_log->log_component[ENB_APP].filelog = 0; g_log->log_component[ENB_APP].filelog_name = ""; g_log->log_component[TMR].name = "TMR"; g_log->log_component[TMR].level = LOG_EMERG; g_log->log_component[TMR].flag = LOG_MED; g_log->log_component[TMR].interval = 1; g_log->log_component[TMR].fd = 0; g_log->log_component[TMR].filelog = 0; g_log->log_component[TMR].filelog_name = ""; g_log->log_component[USIM].name = "USIM"; g_log->log_component[USIM].level = LOG_DEBUG; g_log->log_component[USIM].flag = LOG_NONE; g_log->log_component[USIM].interval = 1; g_log->log_component[USIM].fd = 0; g_log->log_component[USIM].filelog = 0; g_log->log_component[USIM].filelog_name = "/tmp/usim.txt"; /* following log component are used for the localization*/ g_log->log_component[LOCALIZE].name = "LOCALIZE"; g_log->log_component[LOCALIZE].level = LOG_EMERG; g_log->log_component[LOCALIZE].flag = LOG_MED; g_log->log_component[LOCALIZE].interval = 1; g_log->log_component[LOCALIZE].fd = 0; g_log->log_component[LOCALIZE].filelog = 0; g_log->log_component[LOCALIZE].filelog_name = "/tmp/localize.log"; #endif // ! defined(CN_BUILD) g_log->log_component[NAS].name = "NAS"; g_log->log_component[NAS].level = LOG_TRACE; g_log->log_component[NAS].flag = LOG_MED; g_log->log_component[NAS].interval = 1; g_log->log_component[NAS].fd = 0; g_log->log_component[NAS].filelog = 0; g_log->log_component[NAS].filelog_name = "/tmp/nas.log"; g_log->log_component[UDP_].name = "UDP"; g_log->log_component[UDP_].level = LOG_EMERG; g_log->log_component[UDP_].flag = LOG_FULL; g_log->log_component[UDP_].interval = 1; g_log->log_component[UDP_].fd = 0; g_log->log_component[UDP_].filelog = 0; g_log->log_component[UDP_].filelog_name = ""; g_log->log_component[GTPU].name = "GTPV1U"; g_log->log_component[GTPU].level = LOG_EMERG; g_log->log_component[GTPU].flag = LOG_FULL; g_log->log_component[GTPU].interval = 1; g_log->log_component[GTPU].fd = 0; g_log->log_component[GTPU].filelog = 0; g_log->log_component[GTPU].filelog_name = ""; g_log->log_component[S1AP].name = "S1AP"; g_log->log_component[S1AP].level = LOG_EMERG; g_log->log_component[S1AP].flag = LOG_FULL; g_log->log_component[S1AP].interval = 1; g_log->log_component[S1AP].fd = 0; g_log->log_component[S1AP].filelog = 0; g_log->log_component[S1AP].filelog_name = ""; g_log->log_component[SCTP].name = "SCTP"; g_log->log_component[SCTP].level = LOG_EMERG; g_log->log_component[SCTP].flag = LOG_MED; g_log->log_component[SCTP].interval = 1; g_log->log_component[SCTP].fd = 0; g_log->log_component[SCTP].filelog = 0; g_log->log_component[SCTP].filelog_name = ""; g_log->log_component[RRH].name = "RRH"; g_log->log_component[RRH].level = LOG_EMERG; g_log->log_component[RRH].flag = LOG_MED; g_log->log_component[RRH].interval = 1; g_log->log_component[RRH].fd = 0; g_log->log_component[RRH].filelog = 0; g_log->log_component[RRH].filelog_name = ""; g_log->log_component[X2AP].name = "X2AP"; g_log->log_component[X2AP].level = LOG_EMERG; g_log->log_component[X2AP].flag = LOG_FULL; g_log->log_component[X2AP].interval = 1; g_log->log_component[X2AP].fd = 0; g_log->log_component[X2AP].filelog = 0; g_log->log_component[X2AP].filelog_name = ""; g_log->level2string[LOG_EMERG] = "G"; //EMERG g_log->level2string[LOG_ALERT] = "A"; // ALERT g_log->level2string[LOG_CRIT] = "C"; // CRITIC g_log->level2string[LOG_ERR] = "E"; // ERROR g_log->level2string[LOG_WARNING] = "W"; // WARNING g_log->level2string[LOG_NOTICE] = "N"; // NOTICE g_log->level2string[LOG_INFO] = "I"; //INFO g_log->level2string[LOG_DEBUG] = "D"; // DEBUG g_log->level2string[LOG_FILE] = "F"; // file g_log->level2string[LOG_TRACE] = "T"; // TRACE g_log->onlinelog = 1; //online log file g_log->syslog = 0; g_log->filelog = 0; g_log->level = LOG_TRACE; g_log->flag = LOG_LOW; #ifndef RTAI g_log->config.remote_ip = 0; g_log->config.remote_level = LOG_EMERG; g_log->config.facility = LOG_LOCAL7; g_log->config.audit_ip = 0; g_log->config.audit_facility = LOG_LOCAL6; g_log->config.format = 0x00; // online debug inactive g_log->filelog_name = "/tmp/openair.log"; if (g_log->syslog) { #if ! defined(CN_BUILD) openlog(g_log->log_component[EMU].name, LOG_PID, g_log->config.facility); #endif // ! defined(CN_BUILD) } if (g_log->filelog) { gfd = open(g_log->filelog_name, O_WRONLY | O_CREAT, 0666); } // could put a loop here to check for all comps for (i=MIN_LOG_COMPONENTS; i < MAX_LOG_COMPONENTS; i++) { if (g_log->log_component[i].filelog == 1 ) { g_log->log_component[i].fd = open(g_log->log_component[i].filelog_name, O_WRONLY | O_CREAT | O_APPEND, 0666); } } #else g_log->syslog = 0; g_log->filelog = 0; rtf_create (FIFO_PRINTF_NO, FIFO_PRINTF_SIZE); #endif #ifdef USER_MODE printf("log init done\n"); #else printk("log init done\n"); #endif return 0; } //log record: add to a list void logRecord(const char *file, const char *func, int line, int comp, int level, const char *format, ...) { va_list args; LOG_params log_params; int len; va_start(args, format); len = vsnprintf(log_params.l_buff_info, MAX_LOG_INFO-1, format, args); va_end(args); //2 first parameters must be passed as 'const' to the thread function log_params.file = strdup(file); log_params.func = strdup(func); log_params.line = line; log_params.comp = comp; log_params.level = level; log_params.format = format; log_params.len = len; if (pthread_mutex_lock(&log_lock) != 0) { return; } log_list_tail++; log_list[log_list_tail - 1] = log_params; if (log_list_tail >= 1000) { log_list_tail = 0; } if (log_list_nb_elements < 1000) { log_list_nb_elements++; } if(pthread_cond_signal(&log_notify) != 0) { pthread_mutex_unlock(&log_lock); return; } if(pthread_mutex_unlock(&log_lock) != 0) { return; } //log = malloc(sizeof(LOG_elt)); //log->next = NULL; //log->log_params = log_params; /* Add log task to queue */ //log_list_add_tail_eurecom(log, &log_list); } void logRecord_thread_safe(const char *file, const char *func, int line, int comp, int level, int len, const char *params_string) { log_component_t *c; int total_len = 0; 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) && ((c->level > g_log->level) || (level > c->level) || (level > g_log->level))) { return; } VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD, VCD_FUNCTION_IN); // 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 )) { total_len = snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - 1, "%s", params_string); } else { if ((g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR)) { total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "%s", log_level_highlight_start[level]); } if ((g_log->flag & FLAG_COMP) || (c->flag & FLAG_COMP) ) { total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s]", g_log->log_component[comp].name); } if ((g_log->flag & FLAG_LEVEL) || (c->flag & FLAG_LEVEL)) { total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s]", g_log->level2string[level]); } if ((g_log->flag & FLAG_FUNCT) || (c->flag & FLAG_FUNCT)) { total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s] ", func); } if ((g_log->flag & FLAG_FILE_LINE) || (c->flag & FLAG_FILE_LINE) ) { total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s:%d]", file, line); } len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - len, "%s", params_string); if ((g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR)) { total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "%s", log_level_highlight_end[level]); } } // 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 fprintf(stdout, "%s", log_buffer); #endif } #ifndef RTAI if (g_log->syslog) { syslog(g_log->level, "%s", log_buffer); } if (g_log->filelog) { if (write(gfd, log_buffer, total_len) < total_len) { // TODO assert ? } } if ((g_log->log_component[comp].filelog) && (level == LOG_FILE)) { if (write(g_log->log_component[comp].fd, log_buffer, total_len) < total_len) { // TODO assert ? } } #endif VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD, VCD_FUNCTION_OUT); } #if !defined(LOG_NO_THREAD) void *log_thread_function(void *list) { LOG_params log_params; for(;;) { //log_elt = NULL; /* Lock must be taken to wait on conditional variable */ pthread_mutex_lock(&log_lock); /* Wait on condition variable, check for spurious wakeups. When returning from pthread_cond_wait(), we own the lock. */ // sleep while((log_list_nb_elements == 0) && (log_shutdown == 0)) { pthread_cond_wait(&log_notify, &log_lock); } // exit if ((log_shutdown==1) && (log_list_nb_elements == 0)) { break; } /* Grab our task */ //log_elt = log_list_remove_head(&log_list); log_params = log_list[log_list_head]; log_list_head++; log_list_nb_elements--; if (log_list_head >= 1000) { log_list_head = 0; } /* Unlock */ pthread_mutex_unlock(&log_lock); /* Get to work */ logRecord_thread_safe(log_params.file, log_params.func, log_params.line, log_params.comp, log_params.level, log_params.len, log_params.l_buff_info); //free(log_elt); } } #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, ...) { int len = 0; va_list args; log_component_t *c; char *log_start; char *log_end; 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 = c->log_buffer; len = vsnprintf(c->log_buffer, MAX_LOG_TOTAL-1, format, args); log_end = c->log_buffer + len; } else { if ( (g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR) ) { len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "%s", log_level_highlight_start[level]); } log_start = c->log_buffer + len; if ( (g_log->flag & FLAG_COMP) || (c->flag & FLAG_COMP) ) { len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s]", g_log->log_component[comp].name); } if ( (g_log->flag & FLAG_LEVEL) || (c->flag & FLAG_LEVEL) ) { len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s]", g_log->level2string[level]); } if ( (g_log->flag & FLAG_FUNCT) || (c->flag & FLAG_FUNCT) ) { len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s] ", func); } if ( (g_log->flag & FLAG_FILE_LINE) || (c->flag & FLAG_FILE_LINE) ) { len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s:%d]", file, line); } len += vsnprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, format, args); log_end = c->log_buffer + len; if ( (g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR) ) { len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "%s", log_level_highlight_end[level]); } } 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, c->log_buffer, len); } #else fwrite(c->log_buffer, len, 1, stdout); #endif #ifndef RTAI if (g_log->syslog) { syslog(g_log->level, "%s", c->log_buffer); } if (g_log->filelog) { if (write(gfd, c->log_buffer, len) < len) { // TODO assert ? } } if ((g_log->log_component[comp].filelog) && (level == LOG_FILE)) { if (write(g_log->log_component[comp].fd, c->log_buffer, len) < len) { // TODO assert ? } } #else // online print messges if ((g_log->log_component[comp].filelog) && (level == LOG_FILE)) { printf(c->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, 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, VCD_FUNCTION_OUT); } int set_log(int component, int level, int interval) { /* Checking parameters */ DevCheck((component >= MIN_LOG_COMPONENTS) && (component < MAX_LOG_COMPONENTS), component, MIN_LOG_COMPONENTS, MAX_LOG_COMPONENTS); DevCheck((level <= LOG_TRACE) && (level >= LOG_EMERG), level, LOG_TRACE, LOG_EMERG); DevCheck((interval > 0) && (interval <= 0xFF), interval, 0, 0xFF); g_log->log_component[component].level = level; switch (level) { case LOG_TRACE: g_log->log_component[component].flag = LOG_MED ; break; case LOG_DEBUG: g_log->log_component[component].flag = LOG_MED ; break; case LOG_INFO: g_log->log_component[component].flag = LOG_LOW ; break; default: g_log->log_component[component].flag = LOG_NONE ; break; } g_log->log_component[component].interval = interval; return 0; } int set_comp_log(int component, int level, int verbosity, int interval) { /* Checking parameters */ DevCheck((component >= MIN_LOG_COMPONENTS) && (component < MAX_LOG_COMPONENTS), component, MIN_LOG_COMPONENTS, MAX_LOG_COMPONENTS); DevCheck((level <= LOG_TRACE) && (level >= LOG_EMERG), level, LOG_TRACE, LOG_EMERG); DevCheck((interval > 0) && (interval <= 0xFF), interval, 0, 0xFF); if ((verbosity == LOG_NONE) || (verbosity == LOG_LOW) || (verbosity == LOG_MED) || (verbosity == LOG_FULL) || (verbosity == LOG_HIGH)) { g_log->log_component[component].flag = verbosity; } g_log->log_component[component].level = level; g_log->log_component[component].interval = interval; return 0; } void set_glog(int level, int verbosity) { g_log->level = level; g_log->flag = verbosity; } void set_glog_syslog(int enable) { g_log->syslog = enable; } void set_glog_onlinelog(int enable) { g_log->onlinelog = enable; } void set_glog_filelog(int enable) { g_log->filelog = enable; } void set_component_filelog(int comp) { if (g_log->log_component[comp].filelog == 0) { g_log->log_component[comp].filelog = 1; #ifndef RTAI if (g_log->log_component[comp].fd == 0) { g_log->log_component[comp].fd = open(g_log->log_component[comp].filelog_name, O_WRONLY | O_CREAT | O_TRUNC, 0666); } #else #endif } } /* * for the two functions below, the passed array must have a final entry * with string value NULL */ /* map a string to an int. Takes a mapping array and a string as arg */ int map_str_to_int(mapping *map, const char *str) { while (1) { if (map->name == NULL) { return(-1); } if (!strcmp(map->name, str)) { return(map->value); } map++; } } /* map an int to a string. Takes a mapping array and a value */ char *map_int_to_str(mapping *map, int val) { while (1) { if (map->name == NULL) { return NULL; } if (map->value == val) { return map->name; } map++; } } int is_newline( char *str, int size) { int i; for ( i = 0; i < size; i++ ) { if ( str[i] == '\n' ) { return 1; } } /* if we get all the way to here, there must not have been a newline! */ return 0; } void logClean (void) { #ifdef RTAI rtf_destroy (FIFO_PRINTF_NO); #else int i; if (g_log->syslog) { closelog(); } if (g_log->filelog) { close(gfd); } for (i=MIN_LOG_COMPONENTS; i < MAX_LOG_COMPONENTS; i++) { if (g_log->log_component[i].filelog) { close(g_log->log_component[i].fd); } } #endif } #if defined(ENABLE_ITTI) void log_set_instance_type (log_instance_type_t instance) { log_instance_type = instance; } #endif #ifdef LOG_TEST int main(int argc, char *argv[]) { logInit(); //set_log_syslog(1); test_log(); return 1; } int test_log(void) { LOG_ENTER(MAC); // because the default level is DEBUG LOG_I(EMU, "1 Starting OAI logs version %s Build date: %s on %s\n", BUILD_VERSION, BUILD_DATE, BUILD_HOST); LOG_D(MAC, "1 debug MAC \n"); LOG_N(MAC, "1 notice MAC \n"); LOG_W(MAC, "1 warning MAC \n"); set_comp_log(EMU, LOG_INFO, FLAG_ONLINE); set_comp_log(MAC, LOG_WARNING, 0); LOG_I(EMU, "2 Starting OAI logs version %s Build date: %s on %s\n", BUILD_VERSION, BUILD_DATE, BUILD_HOST); LOG_E(MAC, "2 emerge MAC\n"); LOG_D(MAC, "2 debug MAC \n"); LOG_N(MAC, "2 notice MAC \n"); LOG_W(MAC, "2 warning MAC \n"); LOG_I(MAC, "2 info MAC \n"); set_comp_log(MAC, LOG_NOTICE, 1); LOG_ENTER(MAC); LOG_I(EMU, "3 Starting OAI logs version %s Build date: %s on %s\n", BUILD_VERSION, BUILD_DATE, BUILD_HOST); LOG_D(MAC, "3 debug MAC \n"); LOG_N(MAC, "3 notice MAC \n"); LOG_W(MAC, "3 warning MAC \n"); LOG_I(MAC, "3 info MAC \n"); set_comp_log(MAC, LOG_DEBUG,1); set_comp_log(EMU, LOG_DEBUG,1); LOG_ENTER(MAC); LOG_I(EMU, "4 Starting OAI logs version %s Build date: %s on %s\n", BUILD_VERSION, BUILD_DATE, BUILD_HOST); LOG_D(MAC, "4 debug MAC \n"); LOG_N(MAC, "4 notice MAC \n"); LOG_W(MAC, "4 warning MAC \n"); LOG_I(MAC, "4 info MAC \n"); set_comp_log(MAC, LOG_DEBUG,0); set_comp_log(EMU, LOG_DEBUG,0); LOG_I(LOG, "5 Starting OAI logs version %s Build date: %s on %s\n", BUILD_VERSION, BUILD_DATE, BUILD_HOST); LOG_D(MAC, "5 debug MAC \n"); LOG_N(MAC, "5 notice MAC \n"); LOG_W(MAC, "5 warning MAC \n"); LOG_I(MAC, "5 info MAC \n"); set_comp_log(MAC, LOG_TRACE,0X07F); set_comp_log(EMU, LOG_TRACE,0X07F); LOG_ENTER(MAC); LOG_I(LOG, "6 Starting OAI logs version %s Build date: %s on %s\n", BUILD_VERSION, BUILD_DATE, BUILD_HOST); LOG_D(MAC, "6 debug MAC \n"); LOG_N(MAC, "6 notice MAC \n"); LOG_W(MAC, "6 warning MAC \n"); LOG_I(MAC, "6 info MAC \n"); LOG_EXIT(MAC); return 0; } #endif