From 2a80ad67fbe004dd36f73c086d465ee4ea4cf997 Mon Sep 17 00:00:00 2001
From: Leo Yuriev <leo@yuriev.ru>
Date: Tue, 11 Apr 2017 12:55:16 +0300
Subject: [PATCH] test: refine logging.

---
 test/config.cc | 100 ++++++++++++++++++++++---------------------
 test/config.h  |   2 +-
 test/log.cc    | 114 ++++++++++++++++++++++++++++++++++++++-----------
 test/log.h     |  39 +++++++++++++----
 test/main.cc   |  10 ++---
 test/test.cc   |  13 +++---
 test/test.h    |   4 +-
 7 files changed, 187 insertions(+), 95 deletions(-)

diff --git a/test/config.cc b/test/config.cc
index fd9bc732..b1f73368 100644
--- a/test/config.cc
+++ b/test/config.cc
@@ -231,94 +231,98 @@ const struct option_verb table_bits[] = {
     {"data.dups", MDB_DUPSORT},
     {nullptr, 0}};
 
-static void dump_verbs(FILE *out, const char *caption, size_t bits,
+static void dump_verbs(const char *caption, size_t bits,
                        const struct option_verb *verbs) {
-  fprintf(out, "%s: (%" PRIu64 ")", caption, (uint64_t)bits);
+  log_info("%s: 0x%" PRIx64 " = ", caption, (uint64_t)bits);
 
+  const char *comma = "";
   while (verbs->mask && bits) {
     if ((bits & verbs->mask) == verbs->mask) {
-      fprintf(out, ", %s", verbs->verb);
+      logging::feed("%s%s", comma, verbs->verb);
       bits -= verbs->mask;
+      comma = ", ";
     }
     ++verbs;
   }
 
-  fprintf(out, "\n");
+  logging::feed("\n");
 }
 
-static void dump_duration(FILE *out, const char *caption, unsigned duration) {
-  fprintf(out, "%s: ", caption);
+static void dump_duration(const char *caption, unsigned duration) {
+  log_info("%s: ", caption);
   if (duration) {
     if (duration > 24 * 3600)
-      fprintf(out, "%u_", duration / (24 * 3600));
+      logging::feed("%u_", duration / (24 * 3600));
     if (duration > 3600)
-      fprintf(out, "%02u:", (duration % (24 * 3600)) / 3600);
-    fprintf(out, "%02u:%02u", (duration % 3600) / 60, duration % 60);
-  } else
-    fprintf(out, "INFINITE");
-  fprintf(out, "\n");
+      logging::feed("%02u:", (duration % (24 * 3600)) / 3600);
+    logging::feed("%02u:%02u", (duration % 3600) / 60, duration % 60);
+  } else {
+    logging::feed("INFINITE");
+  }
+  logging::feed("\n");
 }
 
-void dump(FILE *out) {
+void dump(const char *title) {
+  logging::local_suffix indent(title);
+
   for (auto i = global::actors.begin(); i != global::actors.end(); ++i) {
-    fprintf(out, "testcase %s\n", testcase2str(i->testcase));
-    if (i->id)
-      fprintf(out, "\tid/table %u\n", i->id);
+    log_info("#%u, testcase %s, id/table %u\n", i->order,
+             testcase2str(i->testcase), i->id);
+    indent.push();
 
     if (i->params.loglevel) {
-      fprintf(out, "\tlog: level %u, %s\n", i->params.loglevel,
-              i->params.pathname_log.empty() ? "console"
-                                             : i->params.pathname_log.c_str());
+      log_info("log: level %u, %s\n", i->params.loglevel,
+               i->params.pathname_log.empty() ? "console"
+                                              : i->params.pathname_log.c_str());
     }
 
-    fprintf(out, "\tdatabase: %s, size %" PRIu64 "\n",
-            i->params.pathname_db.c_str(), i->params.size);
+    log_info("database: %s, size %" PRIu64 "\n", i->params.pathname_db.c_str(),
+             i->params.size);
 
-    dump_verbs(out, "\tmode", i->params.mode_flags, mode_bits);
-    dump_verbs(out, "\ttable", i->params.table_flags, table_bits);
+    dump_verbs("mode", i->params.mode_flags, mode_bits);
+    dump_verbs("table", i->params.table_flags, table_bits);
 
-    fprintf(out, "\tseed %u\n", i->params.seed);
+    log_info("seed %u\n", i->params.seed);
 
     if (i->params.test_nrecords)
-      fprintf(out, "\trecords %u\n", i->params.test_nrecords);
+      log_info("records %u\n", i->params.test_nrecords);
     else
-      dump_duration(out, "\tduration", i->params.test_duration);
+      dump_duration("duration", i->params.test_duration);
 
     if (i->params.nrepeat)
-      fprintf(out, "\trepeat %u\n", i->params.nrepeat);
+      log_info("repeat %u\n", i->params.nrepeat);
     else
-      fprintf(out, "\trepeat ETERNALLY\n");
+      log_info("repeat ETERNALLY\n");
 
-    fprintf(out, "\tthreads %u\n", i->params.nthreads);
+    log_info("threads %u\n", i->params.nthreads);
 
-    fprintf(out, "\tkey: minlen %u, maxlen %u\n", i->params.keylen_min,
-            i->params.keylen_max);
-    fprintf(out, "\tdata: minlen %u, maxlen %u\n", i->params.datalen_min,
-            i->params.datalen_max);
+    log_info("key: minlen %u, maxlen %u\n", i->params.keylen_min,
+             i->params.keylen_max);
+    log_info("data: minlen %u, maxlen %u\n", i->params.datalen_min,
+             i->params.datalen_max);
 
-    fprintf(out, "\tbatch: read %u, write %u\n", i->params.batch_read,
-            i->params.batch_write);
+    log_info("batch: read %u, write %u\n", i->params.batch_read,
+             i->params.batch_write);
 
     if (i->params.waitfor_nops)
-      fprintf(out, "\twait: actor %u for %u ops\n", i->wait4id,
-              i->params.waitfor_nops);
+      log_info("wait: actor %u for %u ops\n", i->wait4id,
+               i->params.waitfor_nops);
     else if (i->params.delaystart)
-      dump_duration(out, "\tdelay", i->params.delaystart);
+      dump_duration("delay", i->params.delaystart);
     else
-      fprintf(out, "\tno-delay\n");
+      log_info("no-delay\n");
 
-    fprintf(out, "\tlimits: readers %u, tables %u\n", i->params.max_readers,
-            i->params.max_tables);
+    log_info("limits: readers %u, tables %u\n", i->params.max_readers,
+             i->params.max_tables);
 
-    fprintf(out, "\tdrop table: %s\n", i->params.drop_table ? "Yes" : "No");
-
-    fprintf(out, "\t#---\n");
+    log_info("drop table: %s\n", i->params.drop_table ? "Yes" : "No");
+    indent.pop();
   }
 
-  dump_duration(out, "timeout", global::config::timeout);
-  fprintf(out, "cleanup: before %s, after %s\n",
-          global::config::dont_cleanup_before ? "No" : "Yes",
-          global::config::dont_cleanup_after ? "No" : "Yes");
+  dump_duration("timeout", global::config::timeout);
+  log_info("cleanup: before %s, after %s\n",
+           global::config::dont_cleanup_before ? "No" : "Yes",
+           global::config::dont_cleanup_after ? "No" : "Yes");
 }
 
 } /* namespace config */
diff --git a/test/config.h b/test/config.h
index c16eca9a..38bc0b22 100644
--- a/test/config.h
+++ b/test/config.h
@@ -108,7 +108,7 @@ struct actor_config_pod {
 
 extern const struct option_verb mode_bits[];
 extern const struct option_verb table_bits[];
-void dump(FILE *out);
+void dump(const char *title = "config-dump: ");
 
 } /* namespace config */
 
diff --git a/test/log.cc b/test/log.cc
index 75993d98..7def0b84 100644
--- a/test/log.cc
+++ b/test/log.cc
@@ -14,13 +14,15 @@
 
 #include "test.h"
 
+static void fflushall() { fflush(nullptr); }
+
 void failure(const char *fmt, ...) {
   va_list ap;
   fflush(NULL);
   va_start(ap, fmt);
-  loggging::output(loggging::failure, fmt, ap);
+  logging::output(logging::failure, fmt, ap);
   va_end(ap);
-  fflush(NULL);
+  fflushall();
   exit(EXIT_FAILURE);
 }
 
@@ -35,10 +37,12 @@ void __noreturn failure_perror(const char *what, int errnum) {
 
 //-----------------------------------------------------------------------------
 
-namespace loggging {
+namespace logging {
 
 static std::string prefix;
+static std::string suffix;
 static loglevel level;
+static FILE *last;
 
 void setup(loglevel _level, const std::string &_prefix) {
   level = (_level > error) ? failure : _level;
@@ -68,61 +72,123 @@ const char *level2str(const loglevel level) {
 
 void output(loglevel priority, const char *format, va_list ap) {
   if (priority >= level) {
-    FILE *out = (priority >= error) ? stderr : stdout;
-    fprintf(out, "[ %u %-10s %6s ] " /* TODO */, osal_getpid(), prefix.c_str(),
-            level2str(priority));
-    vfprintf(out, format, ap);
+    last = (priority >= error) ? stderr : stdout;
+    fprintf(last, "[ %u %-10s %6s ] %s" /* TODO */, osal_getpid(),
+            prefix.c_str(), level2str(priority), suffix.c_str());
+    vfprintf(last, format, ap);
+
     size_t len = strlen(format);
-    if (len && format[len - 1] != '\n')
-      putc('\n', out);
+    char end = len ? format[len - 1] : '\0';
+    switch (end) {
+    default:
+      putc('\n', last);
+    case '\n':
+      if (priority > info)
+        fflushall();
+      break;
+    case ' ':
+    case '_':
+    case ':':
+    case '|':
+    case ',':
+    case '\t':
+    case '\b':
+    case '\r':
+    case '\0':
+      return;
+    }
+  }
+  last = nullptr;
+}
+
+void feed(const char *format, ...) {
+  if (last) {
+    va_list ap;
+    va_start(ap, format);
+    vfprintf(last, format, ap);
+    va_end(ap);
+
+    size_t len = strlen(format);
+    if (len && format[len - 1] == '\n')
+      last = nullptr;
   }
 }
 
+local_suffix::local_suffix(const char *c_str)
+    : trim_pos(suffix.size()), indent(0) {
+  suffix.append(c_str);
+}
+
+local_suffix::local_suffix(const std::string &str)
+    : trim_pos(suffix.size()), indent(0) {
+  suffix.append(str);
+}
+
+void local_suffix::push() {
+  indent += 1;
+  suffix.push_back('\t');
+}
+
+void local_suffix::pop() {
+  assert(indent > 0);
+  if (indent > 0) {
+    indent -= 1;
+    suffix.pop_back();
+  }
+}
+
+local_suffix::~local_suffix() { suffix.erase(trim_pos); }
+
 } /* namespace log */
 
 void log_trace(const char *msg, ...) {
-  if (loggging::trace >= loggging::level) {
+  if (logging::trace >= logging::level) {
     va_list ap;
     va_start(ap, msg);
-    loggging::output(loggging::trace, msg, ap);
+    logging::output(logging::trace, msg, ap);
     va_end(ap);
-  }
+  } else
+    logging::last = nullptr;
 }
 
 void log_info(const char *msg, ...) {
-  if (loggging::info >= loggging::level) {
+  if (logging::info >= logging::level) {
     va_list ap;
     va_start(ap, msg);
-    loggging::output(loggging::info, msg, ap);
+    logging::output(logging::info, msg, ap);
     va_end(ap);
-  }
+  } else
+    logging::last = nullptr;
 }
 
 void log_notice(const char *msg, ...) {
-  if (loggging::notice >= loggging::level) {
+  if (logging::notice >= logging::level) {
     va_list ap;
     va_start(ap, msg);
-    loggging::output(loggging::notice, msg, ap);
+    logging::output(logging::notice, msg, ap);
     va_end(ap);
-  }
+  } else
+    logging::last = nullptr;
 }
 
 void log_warning(const char *msg, ...) {
-  if (loggging::warning >= loggging::level) {
+  if (logging::warning >= logging::level) {
     va_list ap;
     va_start(ap, msg);
-    loggging::output(loggging::warning, msg, ap);
+    logging::output(logging::warning, msg, ap);
     va_end(ap);
-  }
+  } else
+    logging::last = nullptr;
 }
 
 void log_error(const char *msg, ...) {
-  if (loggging::error >= loggging::level) {
+  if (logging::error >= logging::level) {
     va_list ap;
     va_start(ap, msg);
-    loggging::output(loggging::error, msg, ap);
+    logging::output(logging::error, msg, ap);
     va_end(ap);
-  }
+  } else
+    logging::last = nullptr;
 }
 
 void log_touble(const char *where, const char *what, int errnum) {
diff --git a/test/log.h b/test/log.h
index 627a11a0..868b4ee4 100644
--- a/test/log.h
+++ b/test/log.h
@@ -18,16 +18,19 @@
 
 void __noreturn usage(void);
 
-void __noreturn
 #ifdef __GNUC__
-    __attribute__((format(printf, 1, 2)))
+#define __printf_args(format_index, first_arg)                                 \
+  __attribute__((format(printf, format_index, first_arg)))
+#else
+#define __printf_args(format_index, first_arg)
 #endif
-    failure(const char *fmt, ...);
+
+void __noreturn __printf_args(1, 2) failure(const char *fmt, ...);
 
 void __noreturn failure_perror(const char *what, int errnum);
 const char *test_strerror(int errnum);
 
-namespace loggging {
+namespace logging {
 
 enum loglevel {
   trace,
@@ -43,14 +46,32 @@ void setup(loglevel level, const std::string &prefix);
 void setup(const std::string &prefix);
 
 void output(loglevel priority, const char *format, va_list ap);
+void __printf_args(1, 2) feed(const char *format, ...);
+
+class local_suffix {
+protected:
+  size_t trim_pos;
+  int indent;
+
+public:
+  local_suffix(const local_suffix &) = delete;
+  local_suffix(const local_suffix &&) = delete;
+  const local_suffix &operator=(const local_suffix &) = delete;
+
+  local_suffix(const char *c_str);
+  local_suffix(const std::string &str);
+  void push();
+  void pop();
+  ~local_suffix();
+};
 
 } /* namespace log */
 
-void log_trace(const char *msg, ...);
-void log_info(const char *msg, ...);
-void log_notice(const char *msg, ...);
-void log_warning(const char *msg, ...);
-void log_error(const char *msg, ...);
+void __printf_args(1, 2) log_trace(const char *msg, ...);
+void __printf_args(1, 2) log_info(const char *msg, ...);
+void __printf_args(1, 2) log_notice(const char *msg, ...);
+void __printf_args(1, 2) log_warning(const char *msg, ...);
+void __printf_args(1, 2) log_error(const char *msg, ...);
 
 void log_touble(const char *where, const char *what, int errnum);
 
diff --git a/test/main.cc b/test/main.cc
index 741d86f9..8853ea2f 100644
--- a/test/main.cc
+++ b/test/main.cc
@@ -26,9 +26,9 @@ void actor_params::set_defaults(void) {
   pathname_log = "";
   loglevel =
 #ifdef NDEBUG
-      loggging::notice;
+      logging::notice;
 #else
-      loggging::trace;
+      logging::trace;
 #endif
 
   pathname_db =
@@ -118,7 +118,7 @@ int main(int argc, char *const argv[]) {
   actor_params params;
   params.set_defaults();
   global::config::dump_config = true;
-  loggging::setup((loggging::loglevel)params.loglevel, "main");
+  logging::setup((logging::loglevel)params.loglevel, "main");
   unsigned lastid = 0;
 
   if (argc == 2 && strncmp(argv[1], "--case=", 7) == 0) {
@@ -228,11 +228,11 @@ int main(int argc, char *const argv[]) {
   }
 
   if (global::config::dump_config)
-    config::dump(stdout);
+    config::dump();
 
   bool failed = false;
   if (global::actors.size()) {
-    loggging::setup("overlord");
+    logging::setup("overlord");
 
     if (!global::config::dont_cleanup_before)
       cleanup();
diff --git a/test/test.cc b/test/test.cc
index e6b2ada2..45e59ceb 100644
--- a/test/test.cc
+++ b/test/test.cc
@@ -53,13 +53,13 @@ const char *status2str(actor_status status) {
 
 static void mdbx_debug_logger(int type, const char *function, int line,
                               const char *msg, va_list args) {
-  loggging::loglevel level = loggging::trace;
+  logging::loglevel level = logging::trace;
   if (type & MDBX_DBG_PRINT)
-    level = loggging::info;
+    level = logging::info;
   if (type & MDBX_DBG_ASSERT) {
     log_error("libmdbx assertion failure: %s, %d",
               function ? function : "unknown", line);
-    level = loggging::failure;
+    level = logging::failure;
   }
 
   output(level, msg, args);
@@ -122,7 +122,8 @@ bool testcase::wait4start() {
     log_trace(">> wait4start(%u)", config.wait4id);
     int rc = osal_waitfor(config.wait4id);
     if (rc) {
-      log_trace("<< wait4start(%u), failed %s", test_strerror(rc));
+      log_trace("<< wait4start(%u), failed %s", config.wait4id,
+                test_strerror(rc));
       return false;
     }
     return true;
@@ -167,8 +168,8 @@ bool testcase::teardown() {
 
 bool test_execute(const actor_config &config) {
   const mdbx_pid_t pid = osal_getpid();
-  loggging::setup((loggging::loglevel)config.params.loglevel,
-                  format("child_%u.%u", config.order, config.id));
+  logging::setup((logging::loglevel)config.params.loglevel,
+                 format("child_%u.%u", config.order, config.id));
 
   log_trace(">> wait4barrier");
   osal_wait4barrier();
diff --git a/test/test.h b/test/test.h
index b1ce82af..a119c1e6 100644
--- a/test/test.h
+++ b/test/test.h
@@ -90,8 +90,8 @@ protected:
 public:
   testcase(const actor_config &config, const mdbx_pid_t pid)
       : config(config), pid(pid) {
-    loggging::setup(format("%s_%u.%u", testcase2str(config.testcase),
-                           config.order, config.id));
+    logging::setup(format("%s_%u.%u", testcase2str(config.testcase),
+                          config.order, config.id));
   }
 
   virtual bool setup();