Simplify output handling in unit tests (#494)

- Unit tests respect VERBOSE environment variable,
  which ensures output goes to stdout/stderr.

- When VERBOSE is unset, or set to "0" or "false", then:
    - stdout will show only 1 status line per test
    - stderr will be silent, except for error messages

- When VERBOSE is set to any other value, then
  library and unit test info messages go to stdout.

- When a unit test fails, the user will see a suggestion
  to set VERBOSE=1 to see all the detailed output.
  (TODO: the suggestion doesn't appear on a crash, but that'd be nice)

- Library log lines from unit tests no longer go to /tmp/unit_test.std[out,err]

- Platform_default_log_handle and Platform_error_log_handle are no
  longer part of the public API surface.  Applications (and tests
  that mimic apps) must use platform_set_log_streams() instead.

- Cleans up most unit tests to avoid a direct dependency on platform.h:
  - Removes some references to Platform_*_log_handle globals
    and instead calls platform_set_log_streams()
  - Removes some calls to platform_default_log()
    and instead use a dedicated CTEST_LOG_INFO() macro.
  - This isn't complete, but is a start

- Enable VERBOSE mode when running tests in CI

- fixup: move file_error_returns test to limitations test file, since it covers an error condition

ci/jobs.lib.yml

@@ -15,7 +15,6 @@
 
 
 #@ load("sequences.lib.yml",
-#@         "sequence_pr_build_test",
 #@         "sequence_pr_debug_build_test",
 #@         "sequence_pr_clang_format",
 #@         "sequence_pr_shell_scripts",

ci/steps.lib.yml

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

include/splinterdb/platform_linux/public_platform.h

@@ -67,17 +67,12 @@ typedef int32 bool;
 #endif
 typedef uint8 bool8;
 
-// By default, platform_default_log() messages are sent to /dev/null
-// and platform_error_log() messages go to stderr.
-//
-// Use platform_set_log_streams() to send the log messages elsewhere.
-typedef FILE                platform_log_handle;
-extern platform_log_handle *Platform_default_log_handle;
-extern platform_log_handle *Platform_error_log_handle;
+typedef FILE platform_log_handle;
 
-// Set the streams where informational and error messages will be printed.
+// By default, info messages sent from platform_default_log() go to /dev/null
+// and error messages sent from platform_error_log() go to stderr.
 //
-// These default to /dev/null and stderr, respectively.
+// Use platform_set_log_streams() to send those log messages elsewhere.
 //
 // For example, to send info messages to stdout and errors to stderr, run:
 //    platform_set_log_streams(stdout, stderr);

src/platform_linux/platform.h

@@ -170,12 +170,15 @@ typedef struct {
 extern bool platform_use_hugetlb;
 extern bool platform_use_mlock;
 
+
 /*
  * Section 3:
  * Shared types/typedefs that rely on platform-specific types/typedefs
  * There should not be any generic #includes here, but potentially #includes
  * of headers defined in splinterdb cannot be included until now.
  */
+extern platform_log_handle *Platform_default_log_handle;
+extern platform_log_handle *Platform_error_log_handle;
 
 
 /*

tests/unit/btree_stress_test.c

@@ -234,23 +234,15 @@ CTEST2(btree_stress, test_random_inserts_concurrent)
    if (!iterator_tests(
           (cache *)&data->cc, &data->dbtree_cfg, root_addr, nkvs, data->hid))
    {
-      platform_default_log("invalid ranges in original tree\n");
+      CTEST_ERR("invalid ranges in original tree\n");
    }
 
-   /* platform_default_log("\n\n\n"); */
-   /* btree_print_tree((cache *)&cc, &dbtree_cfg, root_addr); */
-
    uint64 packed_root_addr = pack_tests(
       (cache *)&data->cc, &data->dbtree_cfg, data->hid, root_addr, nkvs);
    if (0 < nkvs && !packed_root_addr) {
       ASSERT_TRUE(FALSE, "Pack failed.\n");
    }
 
-   /* platform_default_log("\n\n\n"); */
-   /* btree_print_tree((cache *)&cc, &dbtree_cfg,
-    * packed_root_addr); */
-   /* platform_default_log("\n\n\n"); */
-
    rc = query_tests((cache *)&data->cc,
                     &data->dbtree_cfg,
                     data->hid,
@@ -493,7 +485,7 @@ pack_tests(cache           *cc,
    if (!SUCCESS(btree_pack(&req))) {
       ASSERT_TRUE(FALSE, "Pack failed! req.num_tuples = %d\n", req.num_tuples);
    } else {
-      platform_default_log("Packed %lu items ", req.num_tuples);
+      CTEST_LOG_INFO("Packed %lu items ", req.num_tuples);
    }
 
    btree_pack_req_deinit(&req, hid);

tests/unit/config_parse_test.c

@@ -41,9 +41,6 @@ CTEST_DATA(config_parse)
 // Optional setup function for suite, called before every test in suite
 CTEST_SETUP(config_parse)
 {
-   Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+");
-   Platform_error_log_handle   = fopen("/tmp/unit_test.stderr", "a+");
-
    uint64 heap_capacity = (1024 * MiB);
    // Create a heap for io, allocator, cache and splinter
    platform_status rc = platform_heap_create(

tests/unit/ctest.h

@@ -79,6 +79,19 @@ struct ctest {
    unsigned int magic;
 };
 
+// If FALSE (default), then CTEST_LOG_INFO() and CTEST_LOG() will no-op.
+extern _Bool Ctest_verbose;
+
+// For immedate logging to stdout
+// (contrast with CTEST_LOG which does buffered/delayed logging to stderr)
+#define CTEST_LOG_INFO(...)                                                    \
+   do {                                                                        \
+      if (Ctest_verbose) {                                                     \
+         fprintf(stdout, __VA_ARGS__);                                         \
+         fflush(stdout);                                                       \
+      }                                                                        \
+   } while (0)
+
 /*
  * Global handles to command-line args are provided so that we can access
  * argc/argv indirectly thru these global variables inside setup methods.

tests/unit/limitations_test.c

@@ -63,24 +63,32 @@ CTEST_DATA(limitations)
  * Setup heap memory to be used later to test Splinter configuration.
  * splinter_test().
  */
-// clang-format off
 CTEST_SETUP(limitations)
 {
-   Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+");
-   Platform_error_log_handle = fopen("/tmp/unit_test.stderr", "a+");
+   // This test exercises error cases, so even when everthing succeeds
+   // it generates lots of "error" messages.
+   // By default, that would go to stderr, which would pollute test output.
+   // Here we ensure those expected error messages are only printed
+   // when the caller sets the VERBOSE env var to opt-in.
+   if (Ctest_verbose) {
+      platform_set_log_streams(stdout, stderr);
+      CTEST_LOG_INFO("\nVerbose mode on.  This test exercises an error case, "
+                     "so on sucess it "
+                     "will print a message that appears to be an error.\n");
+   } else {
+      FILE *dev_null = fopen("/dev/null", "w");
+      ASSERT_NOT_NULL(dev_null);
+      platform_set_log_streams(dev_null, dev_null);
+   }
 
    uint64 heap_capacity = (1 * GiB);
 
    // Create a heap for io, allocator, cache and splinter
-   platform_status rc = platform_heap_create(platform_get_module_id(),
-                                             heap_capacity,
-                                             &data->hh,
-                                             &data->hid);
+   platform_status rc = platform_heap_create(
+      platform_get_module_id(), heap_capacity, &data->hh, &data->hid);
    platform_assert_status_ok(rc);
 }
 
-// clang-format on
-
 /*
  * Tear down memory allocated for various sub-systems. Shutdown Splinter.
  */
@@ -376,6 +384,28 @@ CTEST2(limitations, test_zero_cache_size)
    int rc = splinterdb_create(&cfg, &kvsb);
    ASSERT_NOT_EQUAL(0, rc);
 }
+/*
+ * Check that errors on file-opening are returned, not asserted.
+ * Previously, a user error, e.g. bad file permissions, would
+ * just crash the program.
+ */
+CTEST2(limitations, test_file_error_returns)
+{
+   splinterdb       *kvsb;
+   splinterdb_config cfg;
+   data_config       default_data_cfg;
+
+   default_data_config_init(TEST_MAX_KEY_SIZE, &default_data_cfg);
+   create_default_cfg(&cfg, &default_data_cfg);
+
+   cfg.filename = "/dev/null/this-file-cannot-possibly-be-opened";
+
+   // this will fail, but shouldn't crash!
+   int rc = splinterdb_create(&cfg, &kvsb);
+   ASSERT_NOT_EQUAL(0, rc);
+   // if we've made it this far, at least the application can report
+   // the error and recover!
+}
 
 /*
  * Helper routine to create a valid Splinter configuration using default

tests/unit/main.c

@@ -35,6 +35,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;
+
 /*
  * Global handles to command-line args are provided so that we can access
  * argc/argv indirectly thru these global variables inside setup methods.
@@ -88,6 +91,9 @@ ctest_process_args(const int    argc,
 int
 ctest_is_unit_test(const char *argv0);
 
+static bool
+ctest_get_verbosity();
+
 static int
 suite_all(struct ctest *t);
 
@@ -170,6 +176,8 @@ ctest_main(int argc, const char *argv[])
    signal(SIGSEGV, sighandler);
 #endif
 
+   Ctest_verbose = ctest_get_verbosity();
+
    int program_is_unit_test = ctest_is_unit_test(argv[0]);
 
    int print_list = 0; // Are we processing --list arg?
@@ -340,6 +348,13 @@ ctest_main(int argc, const char *argv[])
             num_skip,
             (t2 - t1) / 1000);
    color_print(color, results);
+
+   if (num_fail > 0 && !Ctest_verbose) {
+      snprintf(results,
+               sizeof(results),
+               "(Rerun with env var VERBOSE=1 to see more log messages)");
+      color_print(color, results);
+   }
    return num_fail;
 }
 
@@ -384,6 +399,22 @@ 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
+ctest_get_verbosity()
+{
+   char *val = getenv("VERBOSE");
+   if (val == NULL) {
+      return 0;
+   }
+   if ((strcmp(val, "0") == 0) || (strcmp(val, "false") == 0)) {
+      return 0;
+   }
+   return 1;
+}
+
 /*
  * ---------------------------------------------------------------------------
  * Process the command-line arguments. The main job of this function is to
@@ -718,6 +749,10 @@ msg_end(void)
 void
 CTEST_LOG(const char *fmt, ...)
 {
+   if (!Ctest_verbose) {
+      return;
+   }
+
    va_list argp;
    msg_start(ANSI_BLUE, "LOG");
 

tests/unit/misc_test.c

@@ -56,9 +56,25 @@ test_vfprintf_usermsg(platform_log_handle *log_handle,
 /*
  * Global data declaration macro:
  */
-CTEST_DATA(misc){};
+CTEST_DATA(misc)
+{
+   FILE *log_output;
+};
 
-CTEST_SETUP(misc) {}
+CTEST_SETUP(misc)
+{
+   // It can be surprising to see errors printed from a successful test run.
+   // So lets send those messages to /dev/null unless VERBOSE=1.
+   if (Ctest_verbose) {
+      data->log_output = stdout;
+      CTEST_LOG_INFO("\nVerbose mode on.  This test exercises error-reporting "
+                     "logic, so on success it will print a message "
+                     "that appears to be an error.\n");
+   } else {
+      data->log_output = fopen("/dev/null", "w");
+      ASSERT_NOT_NULL(data->log_output);
+   }
+}
 
 // Optional teardown function for suite, called after every test in suite
 CTEST_TEARDOWN(misc) {}
@@ -90,7 +106,7 @@ CTEST2(misc, test_assert_basic_msg)
             MISC_MSG_WITH_NO_ARGS);
 
    ASSERT_STREQN(expmsg, assert_str, strlen(expmsg));
-   platform_close_log_stream(&stream, Platform_error_log_handle);
+   platform_close_log_stream(&stream, data->log_output);
 }
 
 /*
@@ -127,7 +143,7 @@ CTEST2(misc, test_assert_msg_with_args)
             arg_name);
 
    ASSERT_STREQN(expmsg, assert_str, strlen(expmsg));
-   platform_close_log_stream(&stream, Platform_error_log_handle);
+   platform_close_log_stream(&stream, data->log_output);
 }
 
 /*
@@ -164,7 +180,7 @@ CTEST2(misc, test_ctest_assert_prints_user_msg_with_params)
                  expmsg,
                  expmsg_len,
                  assert_str);
-   platform_close_log_stream(&stream, Platform_error_log_handle);
+   platform_close_log_stream(&stream, data->log_output);
 }
 
 /* Helper functions follow all test case methods */