mdbx-test: refix logging.

Change-Id: I8852cca84669b4da2a994f2d5d2cec833e21f2f6

src/elements/core.c

@@ -15416,6 +15416,9 @@ __dll_export
 #endif /* MDBX_BUILD_CONFIG */
     ,
     "MDBX_DEBUG=" STRINGIFY(MDBX_DEBUG)
+#ifdef MDBX_LOGLEVEL_BUILD
+    " MDBX_LOGLEVEL_BUILD=" STRINGIFY(MDBX_LOGLEVEL_BUILD)
+#endif /* MDBX_LOGLEVEL_BUILD */
     " MDBX_WORDBITS=" STRINGIFY(MDBX_WORDBITS)
     " BYTE_ORDER="
 #if __BYTE_ORDER__ == __ORDER_LITTLE_ENDIAN__

test/config.cc

@@ -314,7 +314,7 @@ const struct option_verb table_bits[] = {
 
 static void dump_verbs(const char *caption, size_t bits,
                        const struct option_verb *verbs) {
-  log_info("%s: 0x%" PRIx64 " = ", caption, (uint64_t)bits);
+  log_verbose("%s: 0x%" PRIx64 " = ", caption, (uint64_t)bits);
 
   const char *comma = "";
   while (verbs->mask && bits) {
@@ -330,7 +330,7 @@ static void dump_verbs(const char *caption, size_t bits,
 }
 
 static void dump_duration(const char *caption, unsigned duration) {
-  log_info("%s: ", caption);
+  log_verbose("%s: ", caption);
   if (duration) {
     if (duration > 24 * 3600)
       logging::feed("%u_", duration / (24 * 3600));
@@ -347,84 +347,86 @@ void dump(const char *title) {
   logging::local_suffix indent(title);
 
   for (auto i = global::actors.begin(); i != global::actors.end(); ++i) {
-    log_info("#%u, testcase %s, space_id/table %u\n", i->actor_id,
+    log_verbose("#%u, testcase %s, space_id/table %u\n", i->actor_id,
-             testcase2str(i->testcase), i->space_id);
+                testcase2str(i->testcase), i->space_id);
     indent.push();
 
     if (i->params.loglevel) {
-      log_info("log: level %u, %s\n", i->params.loglevel,
+      log_verbose("log: level %u, %s\n", i->params.loglevel,
-               i->params.pathname_log.empty() ? "console"
+                  i->params.pathname_log.empty()
-                                              : i->params.pathname_log.c_str());
+                      ? "console"
+                      : i->params.pathname_log.c_str());
     }
 
-    log_info("database: %s, size %" PRIuPTR "[%" PRIiPTR "..%" PRIiPTR
+    log_verbose("database: %s, size %" PRIuPTR "[%" PRIiPTR "..%" PRIiPTR
-             ", %i %i, %i]\n",
+                ", %i %i, %i]\n",
-             i->params.pathname_db.c_str(), i->params.size_now,
+                i->params.pathname_db.c_str(), i->params.size_now,
-             i->params.size_lower, i->params.size_upper,
+                i->params.size_lower, i->params.size_upper,
-             i->params.shrink_threshold, i->params.growth_step,
+                i->params.shrink_threshold, i->params.growth_step,
-             i->params.pagesize);
+                i->params.pagesize);
 
     dump_verbs("mode", i->params.mode_flags, mode_bits);
     dump_verbs("table", i->params.table_flags, table_bits);
 
     if (i->params.test_nops)
-      log_info("iterations/records %u\n", i->params.test_nops);
+      log_verbose("iterations/records %u\n", i->params.test_nops);
     else
       dump_duration("duration", i->params.test_duration);
 
     if (i->params.nrepeat)
-      log_info("repeat %u\n", i->params.nrepeat);
+      log_verbose("repeat %u\n", i->params.nrepeat);
     else
-      log_info("repeat ETERNALLY\n");
+      log_verbose("repeat ETERNALLY\n");
 
-    log_info("threads %u\n", i->params.nthreads);
+    log_verbose("threads %u\n", i->params.nthreads);
 
-    log_info(
+    log_verbose(
         "keygen.params: case %s, width %u, mesh %u, rotate %u, offset %" PRIu64
         ", split %u/%u\n",
         keygencase2str(i->params.keygen.keycase), i->params.keygen.width,
         i->params.keygen.mesh, i->params.keygen.rotate, i->params.keygen.offset,
         i->params.keygen.split,
         i->params.keygen.width - i->params.keygen.split);
-    log_info("keygen.seed: %u\n", i->params.keygen.seed);
+    log_verbose("keygen.seed: %u\n", i->params.keygen.seed);
-    log_info("key: minlen %u, maxlen %u\n", i->params.keylen_min,
+    log_verbose("key: minlen %u, maxlen %u\n", i->params.keylen_min,
-             i->params.keylen_max);
+                i->params.keylen_max);
-    log_info("data: minlen %u, maxlen %u\n", i->params.datalen_min,
+    log_verbose("data: minlen %u, maxlen %u\n", i->params.datalen_min,
-             i->params.datalen_max);
+                i->params.datalen_max);
 
-    log_info("batch: read %u, write %u\n", i->params.batch_read,
+    log_verbose("batch: read %u, write %u\n", i->params.batch_read,
-             i->params.batch_write);
+                i->params.batch_write);
 
     if (i->params.waitfor_nops)
-      log_info("wait: actor %u for %u ops\n", i->wait4id,
+      log_verbose("wait: actor %u for %u ops\n", i->wait4id,
-               i->params.waitfor_nops);
+                  i->params.waitfor_nops);
     else if (i->params.delaystart)
       dump_duration("delay", i->params.delaystart);
     else
-      log_info("no-delay\n");
+      log_verbose("no-delay\n");
 
     if (i->params.inject_writefaultn)
-      log_info("inject-writefault on %u ops\n", i->params.inject_writefaultn);
+      log_verbose("inject-writefault on %u ops\n",
+                  i->params.inject_writefaultn);
     else
-      log_info("no-inject-writefault\n");
+      log_verbose("no-inject-writefault\n");
 
-    log_info("limits: readers %u, tables %u\n", i->params.max_readers,
+    log_verbose("limits: readers %u, tables %u\n", i->params.max_readers,
-             i->params.max_tables);
+                i->params.max_tables);
 
-    log_info("drop table: %s\n", i->params.drop_table ? "Yes" : "No");
+    log_verbose("drop table: %s\n", i->params.drop_table ? "Yes" : "No");
-    log_info("ignore MDBX_MAP_FULL error: %s\n",
+    log_verbose("ignore MDBX_MAP_FULL error: %s\n",
-             i->params.ignore_dbfull ? "Yes" : "No");
+                i->params.ignore_dbfull ? "Yes" : "No");
     indent.pop();
   }
 
   dump_duration("timeout", global::config::timeout_duration_seconds);
-  log_info("cleanup: before %s, after %s\n",
+  log_verbose("cleanup: before %s, after %s\n",
-           global::config::cleanup_before ? "Yes" : "No",
+              global::config::cleanup_before ? "Yes" : "No",
-           global::config::cleanup_after ? "Yes" : "No");
+              global::config::cleanup_after ? "Yes" : "No");
 
-  log_info("failfast: %s\n", global::config::failfast ? "Yes" : "No");
+  log_verbose("failfast: %s\n", global::config::failfast ? "Yes" : "No");
-  log_info("progress indicator: %s\n",
+  log_verbose("progress indicator: %s\n",
-           global::config::progress_indicator ? "Yes" : "No");
+              global::config::progress_indicator ? "Yes" : "No");
 }
 
 } /* namespace config */

test/log.cc

@@ -20,7 +20,7 @@ void failure(const char *fmt, ...) {
   va_list ap;
   va_start(ap, fmt);
   fflushall();
-  logging::output(logging::failure, fmt, ap);
+  logging::output_ap(logging::failure, fmt, ap);
   va_end(ap);
   fflushall();
   exit(EXIT_FAILURE);
@@ -37,17 +37,17 @@ void __noreturn failure_perror(const char *what, int errnum) {
 
 //-----------------------------------------------------------------------------
 
-static void mdbx_logger(int loglevel, const char *function, int line,
+static void mdbx_logger(int priority, const char *function, int line,
                         const char *msg, va_list args) {
   if (!function)
     function = "unknown";
 
-  if (loglevel == MDBX_LOG_FATAL)
+  if (priority == MDBX_LOG_FATAL)
     log_error("mdbx: fatal failure: %s, %d", function, line);
 
   if (logging::output(
-          logging::loglevel(loglevel),
+          logging::loglevel(priority),
-          strncmp(function, "mdbx_", 5) == 0 ? "%s: " : "mdbx: %s: ", function))
+          strncmp(function, "mdbx_", 5) == 0 ? "%s: " : "mdbx %s: ", function))
     logging::feed_ap(msg, args);
 }
 
@@ -58,14 +58,15 @@ static std::string suffix;
 static loglevel level;
 static FILE *last;
 
-void setlevel(loglevel _level) {
+void setlevel(loglevel priority) {
+  level = priority;
   int rc = mdbx_setup_debug(
-      _level, MDBX_DBG_ASSERT | MDBX_DBG_JITTER | MDBX_DBG_DUMP, mdbx_logger);
+      priority, MDBX_DBG_ASSERT | MDBX_DBG_JITTER | MDBX_DBG_DUMP, mdbx_logger);
   log_trace("set mdbx debug-opts: 0x%02x", rc);
 }
 
-void setup(loglevel _level, const std::string &_prefix) {
+void setup(loglevel priority, const std::string &_prefix) {
-  setlevel(_level);
+  setlevel(priority);
   prefix = _prefix;
 }
 
@@ -81,8 +82,8 @@ const char *level2str(const loglevel alevel) {
     return "trace";
   case debug:
     return "debug";
-  case info:
+  case verbose:
-    return "info";
+    return "verbose";
   case notice:
     return "notice";
   case warning:
@@ -95,24 +96,29 @@ const char *level2str(const loglevel alevel) {
 }
 
 bool output(const loglevel priority, const char *format, ...) {
-  if (priority > level)
+  if (lower(priority, level))
     return false;
 
   va_list ap;
   va_start(ap, format);
-  output(priority, format, ap);
+  output_ap(priority, format, ap);
   va_end(ap);
   return true;
 }
 
-bool output(const logging::loglevel priority, const char *format, va_list ap) {
+bool output_ap(const logging::loglevel priority, const char *format,
+               va_list ap) {
   if (last) {
     putc('\n', last);
     fflush(last);
+    if (last == stderr) {
+      putc('\n', stdout);
+      fflush(stdout);
+    }
     last = nullptr;
   }
 
-  if (priority < level)
+  if (lower(priority, level))
     return false;
 
   chrono::time now = chrono::now_realtime();
@@ -135,7 +141,7 @@ bool output(const logging::loglevel priority, const char *format, va_list ap) {
 
   va_list ones;
   memset(&ones, 0, sizeof(ones)) /* zap MSVC and other stupid compilers */;
-  if (priority >= error)
+  if (same_or_higher(priority, error))
     va_copy(ones, ap);
   vfprintf(last, format, ap);
 
@@ -162,14 +168,15 @@ bool output(const logging::loglevel priority, const char *format, va_list ap) {
     break;
   }
 
-  if (priority >= error) {
+  if (same_or_higher(priority, error)) {
     if (last != stderr) {
       fprintf(stderr, "[ %05u %-10s %.4s ] %s", osal_getpid(), prefix.c_str(),
               level2str(priority), suffix.c_str());
       vfprintf(stderr, format, ones);
-      if (end != '\n')
+      if (end == '\n')
-        putc('\n', stderr);
+        fflush(stderr);
-      fflush(stderr);
+      else
+        last = stderr;
     }
     va_end(ones);
   }
@@ -181,10 +188,18 @@ bool feed_ap(const char *format, va_list ap) {
   if (!last)
     return false;
 
+  if (last == stderr) {
+    va_list ones;
+    va_copy(ones, ap);
+    vfprintf(stdout, format, ones);
+    va_end(ones);
+  }
   vfprintf(last, format, ap);
   size_t len = strlen(format);
   if (len && format[len - 1] == '\n') {
     fflush(last);
+    if (last == stderr)
+      fflush(stdout);
     last = nullptr;
   }
   return true;
@@ -229,70 +244,70 @@ local_suffix::~local_suffix() { suffix.erase(trim_pos); }
 } // namespace logging
 
 void log_extra(const char *msg, ...) {
-  if (logging::extra <= logging::level) {
+  if (logging::same_or_higher(logging::extra, logging::level)) {
     va_list ap;
     va_start(ap, msg);
-    logging::output(logging::extra, msg, ap);
+    logging::output_ap(logging::extra, msg, ap);
     va_end(ap);
   } else
     logging::last = nullptr;
 }
 
 void log_trace(const char *msg, ...) {
-  if (logging::trace <= logging::level) {
+  if (logging::same_or_higher(logging::trace, logging::level)) {
     va_list ap;
     va_start(ap, msg);
-    logging::output(logging::trace, msg, ap);
+    logging::output_ap(logging::trace, msg, ap);
     va_end(ap);
   } else
     logging::last = nullptr;
 }
 
 void log_debug(const char *msg, ...) {
-  if (logging::debug <= logging::level) {
+  if (logging::same_or_higher(logging::debug, logging::level)) {
     va_list ap;
     va_start(ap, msg);
-    logging::output(logging::debug, msg, ap);
+    logging::output_ap(logging::debug, msg, ap);
     va_end(ap);
   } else
     logging::last = nullptr;
 }
 
-void log_info(const char *msg, ...) {
+void log_verbose(const char *msg, ...) {
-  if (logging::info <= logging::level) {
+  if (logging::same_or_higher(logging::verbose, logging::level)) {
     va_list ap;
     va_start(ap, msg);
-    logging::output(logging::info, msg, ap);
+    logging::output_ap(logging::verbose, msg, ap);
     va_end(ap);
   } else
     logging::last = nullptr;
 }
 
 void log_notice(const char *msg, ...) {
-  if (logging::notice <= logging::level) {
+  if (logging::same_or_higher(logging::notice, logging::level)) {
     va_list ap;
     va_start(ap, msg);
-    logging::output(logging::notice, msg, ap);
+    logging::output_ap(logging::notice, msg, ap);
     va_end(ap);
   } else
     logging::last = nullptr;
 }
 
 void log_warning(const char *msg, ...) {
-  if (logging::warning <= logging::level) {
+  if (logging::same_or_higher(logging::warning, logging::level)) {
     va_list ap;
     va_start(ap, msg);
-    logging::output(logging::warning, msg, ap);
+    logging::output_ap(logging::warning, msg, ap);
     va_end(ap);
   } else
     logging::last = nullptr;
 }
 
 void log_error(const char *msg, ...) {
-  if (logging::error <= logging::level) {
+  if (logging::same_or_higher(logging::error, logging::level)) {
     va_list ap;
     va_start(ap, msg);
-    logging::output(logging::error, msg, ap);
+    logging::output_ap(logging::error, msg, ap);
     va_end(ap);
   } else
     logging::last = nullptr;
@@ -303,7 +318,7 @@ void log_trouble(const char *where, const char *what, int errnum) {
 }
 
 bool log_enabled(const logging::loglevel priority) {
-  return (priority >= logging::level);
+  return logging::same_or_higher(priority, logging::level);
 }
 
 void log_flush(void) { fflushall(); }

test/log.h

@@ -27,19 +27,28 @@ enum loglevel {
   extra = MDBX_LOG_EXTRA,
   trace = MDBX_LOG_TRACE,
   debug = MDBX_LOG_DEBUG,
-  info = MDBX_LOG_VERBOSE,
+  verbose = MDBX_LOG_VERBOSE,
   notice = MDBX_LOG_NOTICE,
   warning = MDBX_LOG_WARN,
   error = MDBX_LOG_ERROR,
   failure = MDBX_LOG_FATAL
 };
 
-const char *level2str(const loglevel level);
+inline bool lower(loglevel left, loglevel right) {
-void setup(loglevel level, const std::string &prefix);
+  static_assert(MDBX_LOG_EXTRA > MDBX_LOG_FATAL, "WTF?");
-void setup(const std::string &prefix);
+  return left > right;
-void setlevel(loglevel level);
+}
 
-bool output(const loglevel priority, const char *format, va_list ap);
+inline bool same_or_higher(loglevel left, loglevel right) {
+  return left <= right;
+}
+
+const char *level2str(const loglevel level);
+void setup(loglevel priority, const std::string &prefix);
+void setup(const std::string &prefix);
+void setlevel(loglevel priority);
+
+bool output_ap(const loglevel priority, const char *format, va_list ap);
 bool __printf_args(2, 3)
     output(const loglevel priority, const char *format, ...);
 bool feed_ap(const char *format, va_list ap);
@@ -67,7 +76,7 @@ public:
 void __printf_args(1, 2) log_extra(const char *msg, ...);
 void __printf_args(1, 2) log_trace(const char *msg, ...);
 void __printf_args(1, 2) log_debug(const char *msg, ...);
-void __printf_args(1, 2) log_info(const char *msg, ...);
+void __printf_args(1, 2) log_verbose(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, ...);

test/main.cc

@@ -26,7 +26,7 @@ void actor_params::set_defaults(const std::string &tmpdir) {
   pathname_log = "";
   loglevel =
 #ifdef NDEBUG
-      logging::info;
+      logging::verbose;
 #elif defined(_WIN32) || defined(_WIN64)
       logging::debug;
 #else
@@ -456,8 +456,8 @@ int main(int argc, char *const argv[]) {
         if (!actor)
           continue;
 
-        log_info("actor #%u, id %d, pid %u: %s\n", actor->actor_id,
+        log_verbose("actor #%u, id %d, pid %u: %s\n", actor->actor_id,
-                 actor->space_id, pid, status2str(status));
+                    actor->space_id, pid, status2str(status));
         if (status > as_running) {
           left -= 1;
           if (status != as_successful) {
@@ -480,7 +480,7 @@ int main(int argc, char *const argv[]) {
   log_notice("RESULT: %s\n", failed ? "Failed" : "Successful");
   if (global::config::cleanup_before) {
     if (failed)
-      log_info("skip cleanup");
+      log_verbose("skip cleanup");
     else
       cleanup();
   }

test/test.cc

@@ -265,8 +265,9 @@ void testcase::txn_inject_writefault(MDBX_txn *txn) {
   if (config.params.inject_writefaultn && txn) {
     if (config.params.inject_writefaultn <= nops_completed &&
         (mdbx_txn_flags(txn) & MDBX_RDONLY) == 0) {
-      log_info("== txn_inject_writefault(): got %u nops or more, inject FAULT",
+      log_verbose(
-               config.params.inject_writefaultn);
+          "== txn_inject_writefault(): got %u nops or more, inject FAULT",
+          config.params.inject_writefaultn);
       log_flush();
 #if defined(_WIN32) || defined(_WIN64) || defined(_WINDOWS)
       TerminateProcess(GetCurrentProcess(), 42);
@@ -583,13 +584,13 @@ bool test_execute(const actor_config &config_const) {
       }
 
       if (config.params.nrepeat == 1)
-        log_info("test successed");
+        log_verbose("test successed");
       else {
         if (config.params.nrepeat)
-          log_info("test successed (iteration %zi of %zi)", iter,
+          log_verbose("test successed (iteration %zi of %zi)", iter,
-                   size_t(config.params.nrepeat));
+                      size_t(config.params.nrepeat));
         else
-          log_info("test successed (iteration %zi)", iter);
+          log_verbose("test successed (iteration %zi)", iter);
         config.params.keygen.seed += INT32_C(0xA4F4D37B);
       }
 

test/ttl.cc

@@ -73,8 +73,8 @@ bool testcase_ttl::run() {
   const unsigned count_max = (config.params.batch_write > count_max_lower)
                                  ? config.params.batch_write
                                  : count_max_lower;
-  log_info("ttl: using `batch_read` value %u for window_max", window_max);
+  log_verbose("ttl: using `batch_read` value %u for window_max", window_max);
-  log_info("ttl: using `batch_write` value %u for count_max", count_max);
+  log_verbose("ttl: using `batch_write` value %u for count_max", count_max);
 
   uint64_t seed =
       prng64_map2_white(config.params.keygen.seed) + config.actor_id;