Add initial support for message logging levels, used in unit-tests

This commit does some clean-up and normalizes the behaviour of
interfaces to control outputs from C-unit tests. The main goal
is to reduce voluminous output generated by few unit-tests that
exercise print diagnostic code (which otherwise crashes browsers
when viewing test-run outputs in CI). An additional benefit of this
rework is that we now have a way to run unit-tests to see output
generated at different verbosity levels.

- By default, unit test execution remains silent and only error messags
  will be printed. ctests' main() takes care of setting this up.
- set_log_streams_for_tests() becomes the single-interface that unit
  test code has to invoke, when needed to change the test output's
  verbosity level.
- Small collection of MSG_LEVEL_ levels added to ctest.h

Test execution examples: Run with env-var to see diff outputs:
  VERBOSE=0 (or unset env-var): Default; silent output
  VERBOSE=3 : See error messages
  VERBOSE=6 : See info and error messages
  VERBOSE=7 : See all messages; mainly intended to collect debug output

Makefile

@@ -412,11 +412,13 @@ BTREE_SYS = $(OBJDIR)/$(SRCDIR)/btree.o           \
 #
 $(BINDIR)/$(UNITDIR)/misc_test: $(UTIL_SYS) $(COMMON_UNIT_TESTOBJ)
 
-$(BINDIR)/$(UNITDIR)/util_test: $(UTIL_SYS)
+$(BINDIR)/$(UNITDIR)/util_test: $(UTIL_SYS)            \
+                                $(COMMON_UNIT_TESTOBJ)
 
 $(BINDIR)/$(UNITDIR)/btree_test: $(OBJDIR)/$(UNIT_TESTSDIR)/btree_test_common.o \
                                  $(OBJDIR)/$(TESTS_DIR)/config.o                \
                                  $(OBJDIR)/$(TESTS_DIR)/test_data.o             \
+                                 $(COMMON_UNIT_TESTOBJ)                         \
                                  $(BTREE_SYS)
 
 $(BINDIR)/$(UNITDIR)/btree_stress_test: $(OBJDIR)/$(UNIT_TESTSDIR)/btree_test_common.o  \
@@ -440,7 +442,8 @@ $(BINDIR)/$(UNITDIR)/splinterdb_stress_test: $(COMMON_TESTOBJ)
                                              $(OBJDIR)/$(FUNCTIONAL_TESTSDIR)/test_async.o \
                                              $(LIBDIR)/libsplinterdb.so
 
-$(BINDIR)/$(UNITDIR)/writable_buffer_test: $(UTIL_SYS)
+$(BINDIR)/$(UNITDIR)/writable_buffer_test: $(UTIL_SYS)            \
+                                           $(COMMON_UNIT_TESTOBJ)
 
 $(BINDIR)/$(UNITDIR)/limitations_test: $(COMMON_TESTOBJ)                             \
                                        $(COMMON_UNIT_TESTOBJ)                        \
@@ -450,6 +453,7 @@ $(BINDIR)/$(UNITDIR)/limitations_test: $(COMMON_TESTOBJ)
 $(BINDIR)/$(UNITDIR)/config_parse_test: $(UTIL_SYS)                                   \
                                         $(COMMON_TESTOBJ)                             \
                                         $(OBJDIR)/$(FUNCTIONAL_TESTSDIR)/test_async.o \
+                                        $(COMMON_UNIT_TESTOBJ)                        \
                                         $(LIBDIR)/libsplinterdb.so
 
 $(BINDIR)/$(UNITDIR)/task_system_test: $(UTIL_SYS)                                   \

ci/steps.lib.yml

@@ -105,7 +105,7 @@ config:
     INCLUDE_SLOW_TESTS: #@ str(not quick).lower()
     RUN_NIGHTLY_TESTS: #@ str(test_nightly).lower()
     BUILD_VERBOSE: "1"
-    VERBOSE: "1"
+    VERBOSE: "3"
 
     #! Exercise 'make help' in quick tests mode, to ensure 'help' still works.
     #@ if quick:

src/platform_linux/platform.c

@@ -40,6 +40,13 @@ platform_set_log_streams(platform_log_handle *info_stream,
    Platform_error_log_handle   = error_stream;
 }
 
+// Return the stdout log-stream handle
+platform_log_handle *
+platform_get_stdout_stream(void)
+{
+   return Platform_default_log_handle;
+}
+
 platform_status
 platform_heap_create(platform_module_id    UNUSED_PARAM(module_id),
                      uint32                max,

src/platform_linux/platform.h

@@ -630,6 +630,9 @@ platform_set_tid(threadid t);
 static inline size_t
 platform_strnlen(const char *s, size_t maxlen);
 
+platform_log_handle *
+platform_get_stdout_stream(void);
+
 platform_status
 platform_heap_create(platform_module_id    module_id,
                      uint32                max,

tests/unit/btree_stress_test.c

@@ -113,8 +113,6 @@ CTEST_DATA(btree_stress)
 // Setup function for suite, called before every test in suite
 CTEST_SETUP(btree_stress)
 {
-   set_log_streams_for_error_tests(NULL, NULL);
-
    config_set_defaults(&data->master_cfg);
    data->master_cfg.cache_capacity = GiB_TO_B(5);
    data->data_cfg                  = test_data_config;
@@ -259,11 +257,15 @@ CTEST2(btree_stress, test_random_inserts_concurrent)
    ASSERT_NOT_EQUAL(0, rc, "Invalid ranges in packed tree\n");
 
    // Exercise print method to verify that it basically continues to work.
+   set_log_streams_for_tests(MSG_LEVEL_DEBUG);
+
    btree_print_tree(Platform_default_log_handle,
                     (cache *)&data->cc,
                     &data->dbtree_cfg,
                     packed_root_addr);
 
+   set_log_streams_for_tests(MSG_LEVEL_INFO);
+
    // Release memory allocated in this test case
    for (uint64 i = 0; i < nthreads; i++) {
       platform_free(data->hid, params[i].scratch);

tests/unit/ctest.h

@@ -79,14 +79,26 @@ struct ctest {
    unsigned int magic;
 };
 
+/*
+ * Message verbosity levels: For every message level, all messages at a lower
+ * severity level are also printed. (Modelled on syslog's severity levels.)
+ * See: https://en.wikipedia.org/wiki/Syslog
+ */
+typedef enum msg_level {
+   MSG_LEVEL_SILENT = 0, // No messages are printed
+   MSG_LEVEL_ERRORS = 3, // Only error messages are printed
+   MSG_LEVEL_INFO   = 6, // Informational messages are printed
+   MSG_LEVEL_DEBUG  = 7, // All messages, including debug outputs, are printed
+} msg_level;
+
 // If FALSE (default), then CTEST_LOG_INFO() and CTEST_LOG() will no-op.
-extern _Bool Ctest_verbose;
+extern msg_level Ctest_verbosity;
 
-// For immedate logging to stdout
+// For immediate logging to stdout at any message verbosity level.
 // (contrast with CTEST_LOG which does buffered/delayed logging to stderr)
 #define CTEST_LOG_INFO(...)                                                    \
    do {                                                                        \
-      if (Ctest_verbose) {                                                     \
+      if (Ctest_verbosity >= MSG_LEVEL_INFO) {                                 \
          fprintf(stdout, __VA_ARGS__);                                         \
          fflush(stdout);                                                       \
       }                                                                        \
@@ -322,4 +334,4 @@ assert_dbl_far(double      exp,
       va_end(varargs);                                                         \
    } while (0)
 
-#endif
+#endif /* CTEST_H */

tests/unit/limitations_test.c

@@ -67,7 +67,8 @@ CTEST_DATA(limitations)
  */
 CTEST_SETUP(limitations)
 {
-   set_log_streams_for_error_tests(NULL, NULL);
+   // All test cases in this test usually deal with error handling
+   set_log_streams_for_tests(MSG_LEVEL_ERRORS);
 
    uint64 heap_capacity = (1 * GiB);
 

tests/unit/main.c

@@ -22,6 +22,7 @@
 
 #include "util.h"
 #include "ctest.h"
+#include "unit_tests.h"
 
 #define MSG_SIZE 4096
 
@@ -35,8 +36,9 @@ static const char *testcase_name = NULL;
 
 typedef int (*ctest_filter_func)(struct ctest *);
 
-// If false, then CTEST_LOG_INFO() and CTEST_LOG() will no-op.
-_Bool Ctest_verbose = FALSE;
+// Default: CTEST_LOG_INFO() and CTEST_LOG() will no-op.
+// Will print messages to stdout at any other verbosity level.
+msg_level Ctest_verbosity = MSG_LEVEL_SILENT;
 
 /*
  * Global handles to command-line args are provided so that we can access
@@ -91,7 +93,7 @@ ctest_process_args(const int    argc,
 int
 ctest_is_unit_test(const char *argv0);
 
-static bool
+static msg_level
 ctest_get_verbosity();
 
 static int
@@ -176,7 +178,7 @@ ctest_main(int argc, const char *argv[])
    signal(SIGSEGV, sighandler);
 #endif
 
-   Ctest_verbose = ctest_get_verbosity();
+   Ctest_verbosity = ctest_get_verbosity();
 
    int program_is_unit_test = ctest_is_unit_test(argv[0]);
 
@@ -230,6 +232,11 @@ ctest_main(int argc, const char *argv[])
    struct ctest *ctest_begin = &CTEST_IMPL_TNAME(suite, test);
    struct ctest *ctest_end   = &CTEST_IMPL_TNAME(suite, test);
 
+   // By default, all unit-tests will only report error messages. If you wish
+   // to also see other informational messages from the library, run the
+   // tests with env-var VERBOSE=6 verbosity level.
+   set_log_streams_for_tests(MSG_LEVEL_INFO);
+
    // find begin and end of section by comparing magics
    while (1) {
       struct ctest *t = ctest_begin - 1;
@@ -349,10 +356,11 @@ ctest_main(int argc, const char *argv[])
             (t2 - t1) / 1000);
    color_print(color, results);
 
-   if (num_fail > 0 && !Ctest_verbose) {
+   if (num_fail > 0 && (Ctest_verbosity != MSG_LEVEL_SILENT)) {
       snprintf(results,
                sizeof(results),
-               "(Rerun with env var VERBOSE=1 to see more log messages)");
+               "(Rerun with env var VERBOSE=%d to see more log messages)",
+               MSG_LEVEL_ERRORS);
       color_print(color, results);
    }
    return num_fail;
@@ -399,20 +407,29 @@ ctest_is_unit_test(const char *argv0)
    return 0;
 }
 
-// Determine the log message verbosity to use for this test run.
-// If env var VERBOSE is unset, or is set to "0" or "false", the be quiet.
-// Otherwise, be verbose.
-static bool
+/*
+ * Determine the log message verbosity level to use for this test run.
+ *
+ * If env var VERBOSE is unset, or is set to "0" then be quiet.
+ * If env var VERBOSE=3 then be verbose reporting only errors.
+ * Otherwise, settle for the specified verbosity level.
+ *
+ * Examples:
+ *  - To see only error and informational messages, run as:
+ *     $ VERBOSE=6 bin/unit/task_system_test
+ *
+ *  - To see outputs from a test case that generates diagnostic output, run as:
+ *     $ VERBOSE=7 bin/unit/splinter_test test_splinter_print_diags
+ */
+static msg_level
 ctest_get_verbosity()
 {
    char *val = getenv("VERBOSE");
    if (val == NULL) {
-      return 0;
-   }
-   if ((strcmp(val, "0") == 0) || (strcmp(val, "false") == 0)) {
-      return 0;
+      return MSG_LEVEL_SILENT;
    }
-   return 1;
+   // Expect user to pass-in a legit value.
+   return atoi(val);
 }
 
 /*
@@ -545,6 +562,13 @@ ctest_usage(const char *progname, int program_is_unit_test)
    } else {
       printf("[ --list | [ --<config options> ]* <test-case-name> ]\n");
    }
+   printf(
+      "\nUse env-var VERBOSE=<n> to control verbosity of output from tests.\n");
+   printf("  %d - Or, unset, turns off all output from tests. (Default).\n",
+          MSG_LEVEL_SILENT);
+   printf("  %d - Only error messages are printed.\n", MSG_LEVEL_ERRORS);
+   printf("  %d - All messages, including debugging output is printed.\n",
+          MSG_LEVEL_DEBUG);
 }
 
 /*
@@ -746,10 +770,15 @@ msg_end(void)
    print_errormsg("\n");
 }
 
+/*
+ * CTest message logging interface. By default, all message logging is
+ * "silent"; i.e. turned OFF. Messages will be printed to stderr at any other
+ * verbosity level.
+ */
 void
 CTEST_LOG(const char *fmt, ...)
 {
-   if (!Ctest_verbose) {
+   if (Ctest_verbosity == MSG_LEVEL_SILENT) {
       return;
    }
 

tests/unit/misc_test.c

@@ -13,7 +13,6 @@
 #include "unit_tests.h"
 #include "ctest.h" // This is required for all test-case files.
 #include "util.h"
-#include "platform.h"
 
 #define ASSERT_OUTBUF_LEN 200
 
@@ -68,7 +67,9 @@ CTEST_DATA(misc)
 
 CTEST_SETUP(misc)
 {
-   set_log_streams_for_error_tests(&data->log_output, NULL);
+   // All test cases in this test usually deal with error handling
+   set_log_streams_for_tests(MSG_LEVEL_ERRORS);
+   data->log_output = platform_get_stdout_stream();
 }
 
 // Optional teardown function for suite, called after every test in suite

tests/unit/platform_apis_test.c

@@ -27,8 +27,6 @@ CTEST_DATA(platform_api)
 
 CTEST_SETUP(platform_api)
 {
-   set_log_streams_for_error_tests(NULL, NULL);
-
    platform_status rc = STATUS_OK;
 
    uint64 heap_capacity = (256 * MiB); // small heap is sufficient.
@@ -69,6 +67,7 @@ CTEST2(platform_api, test_platform_buffer_init)
  */
 CTEST2(platform_api, test_platform_buffer_init_fails_for_very_large_length)
 {
+   set_log_streams_for_tests(MSG_LEVEL_ERRORS);
    platform_status rc = STATUS_NO_MEMORY;
 
    buffer_handle bh;
@@ -88,4 +87,6 @@ CTEST2(platform_api, test_platform_buffer_init_fails_for_very_large_length)
    // deinit() would fail horribly when nothing was successfully mmap()'ed
    rc = platform_buffer_deinit(&bh);
    ASSERT_FALSE(SUCCESS(rc));
+
+   set_log_streams_for_tests(MSG_LEVEL_INFO);
 }

tests/unit/splinter_test.c

@@ -114,8 +114,6 @@ CTEST_DATA(splinter)
 // clang-format off
 CTEST_SETUP(splinter)
 {
-   set_log_streams_for_tests();
-
    // Defaults: For basic unit-tests, use single threads
    data->num_insert_threads = 1;
    data->num_lookup_threads = 1;
@@ -634,6 +632,8 @@ CTEST2(splinter, test_lookups)
  */
 CTEST2(splinter, test_splinter_print_diags)
 {
+   set_log_streams_for_tests(MSG_LEVEL_DEBUG);
+
    allocator *alp = (allocator *)&data->al;
 
    trunk_handle *spl = trunk_create(data->splinter_cfg,
@@ -667,6 +667,7 @@ CTEST2(splinter, test_splinter_print_diags)
    allocator_print_stats(alp);
    allocator_print_allocated(alp);
 
+   set_log_streams_for_tests(MSG_LEVEL_INFO);
    trunk_destroy(spl);
 }
 

tests/unit/splinterdb_quick_test.c

@@ -98,8 +98,6 @@ CTEST_DATA(splinterdb_quick)
 // Optional setup function for suite, called before every test in suite
 CTEST_SETUP(splinterdb_quick)
 {
-   set_log_streams_for_tests();
-
    default_data_config_init(TEST_MAX_KEY_SIZE, &data->default_data_cfg.super);
    create_default_cfg(&data->cfg, &data->default_data_cfg.super);
 
@@ -149,7 +147,6 @@ CTEST2(splinterdb_quick, test_basic_flow)
    int rc = splinterdb_lookup(data->kvsb, user_key, &result);
    ASSERT_EQUAL(0, rc);
 
-
    // Lookup of a non-existent key should return not-found.
    ASSERT_FALSE(splinterdb_lookup_found(&result));
 
@@ -195,7 +192,6 @@ CTEST2(splinterdb_quick, test_apis_for_max_key_length)
    memset(large_key_data, 'a', TEST_MAX_KEY_SIZE);
    slice large_key = slice_create(large_key_len, large_key_data);
 
-
    static char *to_insert_data = "a-value";
    size_t       to_insert_len  = strlen(to_insert_data);
    slice        to_insert      = slice_create(to_insert_len, to_insert_data);

tests/unit/splinterdb_stress_test.c

@@ -48,8 +48,6 @@ CTEST_DATA(splinterdb_stress)
 // Setup function for suite, called before every test in suite
 CTEST_SETUP(splinterdb_stress)
 {
-   set_log_streams_for_tests();
-
    data->cfg           = (splinterdb_config){.filename   = TEST_DB_NAME,
                                              .cache_size = 1000 * Mega,
                                              .disk_size  = 9000 * Mega,

tests/unit/task_system_test.c

@@ -104,7 +104,6 @@ CTEST_DATA(task_system)
 CTEST_SETUP(task_system)
 {
    platform_status rc = STATUS_OK;
-   set_log_streams_for_error_tests(NULL, NULL);
 
    uint64 heap_capacity = (256 * MiB); // small heap is sufficient.
    // Create a heap for io and task system to use.
@@ -392,6 +391,7 @@ CTEST2(task_system, test_task_system_creation_with_bg_threads)
 CTEST2(task_system, test_use_all_but_one_threads_for_bg_threads)
 {
    platform_status rc = STATUS_OK;
+   set_log_streams_for_tests(MSG_LEVEL_ERRORS);
 
    // Destroy the task system setup by the harness, by default, w/o bg threads.
    task_system_destroy(data->hid, &data->tasks);
@@ -452,6 +452,7 @@ CTEST2(task_system, test_use_all_but_one_threads_for_bg_threads)
          ASSERT_TRUE(SUCCESS(rc));
       }
    }
+   set_log_streams_for_tests(MSG_LEVEL_INFO);
 }
 
 /* Wrapper function to create Splinter Task system w/o background threads. */