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
2015-05-29 14:50:04 +00:00
parent 920f56da11
commit e5c214ab8c
1 changed files with 287 additions and 0 deletions
@@ -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,