bigger log buffer. Now it is 1024 chars (#649)

Use dynamic string for debug_long() function and known relation of size between log_str and log_filter

lib/include/srslte/common/log_filter.h

@@ -58,6 +58,7 @@ public:
   void warning(const char * message, ...) __attribute__ ((format (printf, 2, 3)));
   void info(const char * message, ...)    __attribute__ ((format (printf, 2, 3)));
   void debug(const char * message, ...)   __attribute__ ((format (printf, 2, 3)));
+  void debug_long(const char* message, ...) __attribute__((format(printf, 2, 3)));
 
   void error_hex(const uint8_t *hex, int size, const char * message, ...)   __attribute__((format (printf, 4, 5)));
   void warning_hex(const uint8_t *hex, int size, const char * message, ...) __attribute__((format (printf, 4, 5)));
@@ -82,14 +83,19 @@ protected:
   logger *logger_h;
   bool    do_tti;
 
-  static const int char_buff_size = 512;
+  static const int char_buff_size = logger::preallocated_log_str_size - 64 * 3;
 
   time_itf      *time_src;
   time_format_t time_format;
 
   logger_stdout def_logger_stdout;
 
-  void all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* msg, const uint8_t* hex = nullptr, int size = 0);
+  void        all_log(srslte::LOG_LEVEL_ENUM level,
+                      uint32_t               tti,
+                      const char*            msg,
+                      const uint8_t*         hex      = nullptr,
+                      int                    size     = 0,
+                      bool                   long_msg = false);
   void        now_time(char* buffer, const uint32_t buffer_len);
   void        get_tti_str(const uint32_t tti_, char* buffer, const uint32_t buffer_len);
   std::string hex_string(const uint8_t *hex, int size);

lib/include/srslte/common/logger.h

@@ -37,16 +37,33 @@ namespace srslte {
 class logger
 {
 public:
+  const static uint32_t preallocated_log_str_size = 1024;
+
   logger() : pool(16 * 1024) {}
 
   class log_str
   {
   public:
-    log_str(const char* msg_) { strncpy(msg, msg_, size); }
+    log_str(const char* msg_ = nullptr, uint32_t size_ = 0)
-    log_str() { reset(); }
+    {
-    void             reset() { msg[0] = '\0'; }
+      size = size_ ? size_ : preallocated_log_str_size;
-    const static int size = 512;
+      msg  = new char[size];
-    char             msg[size];
+      if (msg_) {
+        strncpy(msg, msg_, size);
+      } else {
+        msg[0] = '\0';
+      }
+    }
+    log_str(const log_str&) = delete;
+    log_str& operator=(const log_str&) = delete;
+    ~log_str() { delete[] msg; }
+    void     reset() { msg[0] = '\0'; }
+    char*    str() { return msg; }
+    uint32_t get_buffer_size() { return size; }
+
+  private:
+    uint32_t size;
+    char*    msg;
   };
 
   typedef buffer_pool<log_str> log_str_pool_t;
@@ -61,8 +78,9 @@ public:
         if (pool) {
           buf->reset();
           pool->deallocate(buf);
-        } else
+        } else {
           delete buf;
+        }
       }
     }
 
@@ -75,17 +93,16 @@ public:
 
   virtual void log(unique_log_str_t msg) = 0;
 
-  log_str_pool_t& get_pool() { return pool; }
+  log_str_pool_t&  get_pool() { return pool; }
+  unique_log_str_t allocate_unique_log_str()
+  {
+    return unique_log_str_t(pool.allocate(), logger::log_str_deleter(&pool));
+  }
 
 private:
   log_str_pool_t pool;
 };
 
-inline logger::unique_log_str_t allocate_unique_log_str(logger::log_str_pool_t& pool)
-{
-  return logger::unique_log_str_t(pool.allocate(), logger::log_str_deleter(&pool));
-}
-
 } // namespace srslte
 
 #endif // SRSLTE_LOGGER_H

lib/include/srslte/common/logger_stdout.h

@@ -36,7 +36,7 @@ namespace srslte {
   class logger_stdout : public logger
   {
   public:
-    void log(unique_log_str_t log_str) { fprintf(stdout, "%s", log_str->msg); }
+    void log(unique_log_str_t log_str) { fprintf(stdout, "%s", log_str->str()); }
   };
 
 } // namespace srslte

lib/src/common/log_filter.cc

@@ -65,13 +65,22 @@ void log_filter::init(std::string layer, logger *logger_, bool tti)
   do_tti        = tti;
 }
 
-void log_filter::all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* msg, const uint8_t* hex, int size)
+void log_filter::all_log(
+    srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char* msg, const uint8_t* hex, int size, bool long_msg)
 {
   char buffer_tti[16];
   char buffer_time[64];
 
   if (logger_h) {
-    logger::unique_log_str_t log_str = allocate_unique_log_str(logger_h->get_pool());
+    logger::unique_log_str_t log_str = nullptr;
+
+    if (long_msg) {
+      // For long messages, dynamically allocate a new log_str with enough size outside the pool.
+      uint32_t log_str_msg_len = sizeof(buffer_tti) + sizeof(buffer_time) + 10 + strlen(msg);
+      log_str = logger::unique_log_str_t(new logger::log_str(nullptr, log_str_msg_len), logger::log_str_deleter());
+    } else {
+      log_str = logger_h->allocate_unique_log_str();
+    }
 
     if (log_str) {
       now_time(buffer_time, sizeof(buffer_time));
@@ -79,8 +88,8 @@ void log_filter::all_log(srslte::LOG_LEVEL_ENUM level, uint32_t tti, const char*
         get_tti_str(tti, buffer_tti, sizeof(buffer_tti));
       }
 
-      snprintf(log_str->msg,
+      snprintf(log_str->str(),
-               log_str->size,
+               log_str->get_buffer_size(),
                "%s [%s] %s %s%s%s%s%s",
                buffer_time,
                get_service_name().c_str(),
@@ -108,86 +117,73 @@ void log_filter::console(const char * message, ...) {
   va_end(args);
 }
 
+#define all_log_expand(log_level)                                                                                      \
+  do {                                                                                                                 \
+    if (level >= LOG_LEVEL_ERROR) {                                                                                    \
+      char    args_msg[char_buff_size];                                                                                \
+      va_list args;                                                                                                    \
+      va_start(args, message);                                                                                         \
+      if (vsnprintf(args_msg, char_buff_size, message, args) > 0)                                                      \
+        all_log(LOG_LEVEL_ERROR, tti, args_msg);                                                                       \
+      va_end(args);                                                                                                    \
+    }                                                                                                                  \
+  } while (0)
+
+#define all_log_hex_expand(log_level)                                                                                  \
+  do {                                                                                                                 \
+    if (level >= LOG_LEVEL_ERROR) {                                                                                    \
+      char    args_msg[char_buff_size];                                                                                \
+      va_list args;                                                                                                    \
+      va_start(args, message);                                                                                         \
+      if (vsnprintf(args_msg, char_buff_size, message, args) > 0)                                                      \
+        all_log(LOG_LEVEL_ERROR, tti, args_msg, hex, size);                                                            \
+      va_end(args);                                                                                                    \
+    }                                                                                                                  \
+  } while (0)
+
 void log_filter::error(const char * message, ...) {
-  if (level >= LOG_LEVEL_ERROR) {
+  all_log_expand(LOG_LEVEL_ERROR);
-    char      args_msg[char_buff_size];
-    va_list   args;
-    va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
-      all_log(LOG_LEVEL_ERROR, tti, args_msg);
-    va_end(args);
-  }
 }
+
 void log_filter::warning(const char * message, ...) {
-  if (level >= LOG_LEVEL_WARNING) {
+  all_log_expand(LOG_LEVEL_WARNING);
-    char      args_msg[char_buff_size];
-    va_list   args;
-    va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
-      all_log(LOG_LEVEL_WARNING, tti, args_msg);
-    va_end(args);
-  }
 }
+
 void log_filter::info(const char * message, ...) {
-  if (level >= LOG_LEVEL_INFO) {
+  all_log_expand(LOG_LEVEL_INFO);
-    char      args_msg[char_buff_size];
-    va_list   args;
-    va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
-      all_log(LOG_LEVEL_INFO, tti, args_msg);
-    va_end(args);
-  }
 }
+
 void log_filter::debug(const char * message, ...) {
+  all_log_expand(LOG_LEVEL_DEBUG);
+}
+
+void log_filter::debug_long(const char* message, ...)
+{
   if (level >= LOG_LEVEL_DEBUG) {
-    char      args_msg[char_buff_size];
+    char*     args_msg = NULL;
     va_list   args;
     va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
+    if (vasprintf(&args_msg, message, args) > 0)
-      all_log(LOG_LEVEL_DEBUG, tti, args_msg);
+      all_log(LOG_LEVEL_ERROR, tti, args_msg);
     va_end(args);
+    free(args_msg);
   }
 }
 
 void log_filter::error_hex(const uint8_t *hex, int size, const char * message, ...) {
-  if (level >= LOG_LEVEL_ERROR) {
+  all_log_hex_expand(LOG_LEVEL_ERROR);
-    char      args_msg[char_buff_size];
-    va_list   args;
-    va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
-      all_log(LOG_LEVEL_ERROR, tti, args_msg, hex, size);
-    va_end(args);
-  }
 }
+
 void log_filter::warning_hex(const uint8_t *hex, int size, const char * message, ...) {
-  if (level >= LOG_LEVEL_WARNING) {
+  all_log_hex_expand(LOG_LEVEL_WARNING);
-    char      args_msg[char_buff_size];
-    va_list   args;
-    va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
-      all_log(LOG_LEVEL_WARNING, tti, args_msg, hex, size);
-    va_end(args);
-  }
 }
+
 void log_filter::info_hex(const uint8_t *hex, int size, const char * message, ...) {
-  if (level >= LOG_LEVEL_INFO) {
+  all_log_hex_expand(LOG_LEVEL_INFO);
-    char      args_msg[char_buff_size];
-    va_list   args;
-    va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
-      all_log(LOG_LEVEL_INFO, tti, args_msg, hex, size);
-    va_end(args);
-  }
 }
+
 void log_filter::debug_hex(const uint8_t *hex, int size, const char * message, ...) {
-  if (level >= LOG_LEVEL_DEBUG) {
+  all_log_hex_expand(LOG_LEVEL_DEBUG);
-    char      args_msg[char_buff_size];
-    va_list   args;
-    va_start(args, message);
-    if (vsnprintf(args_msg, char_buff_size, message, args) > 0)
-      all_log(LOG_LEVEL_DEBUG, tti, args_msg, hex, size);
-    va_end(args);
-  }
 }
 
 void log_filter::set_time_src(time_itf *source, time_format_t format) {

lib/src/common/logger_file.cc

@@ -103,9 +103,8 @@ void logger_file::run_thread() {
 
     int n = 0;
     if (logfile) {
-      n = fprintf(logfile, "%s", s->msg);
+      n = fprintf(logfile, "%s", s->str());
     }
-
     buffer.pop_front();
 
     if (n > 0) {
@@ -133,7 +132,7 @@ void logger_file::flush()
   for (it = buffer.begin(); it != buffer.end(); it++) {
     unique_log_str_t s = std::move(*it);
     if (logfile) {
-      fprintf(logfile, "%s", s->msg);
+      fprintf(logfile, "%s", s->str());
     }
   }
   buffer.clear();