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

gapisback · 2023-02-07T01:19:01Z

This commit slightly adjusts the way output messages from C-unit-tests will be printed. Introduce initial set of message logging levels, initially scoped only for use in unit-tests.

For test cases that invoke print / diagnostic code, add support for VERBOSE=7, under which (voluminous) output will be generated. For CI-runs, which set env-var VERBOSE=1, this change will suppress generating large outputs which would otherwise (potentially) cause browsing of test output files to fail.

Default behaviour that unit-tests will print no messages remains. Existing env-var VERBOSE=1, we continue to only print error messages.

NOTE: This PR only partially address the issues raised under issue #534 .

Currently, the main requirement for getting this re-work into /main is to suppress large outputs coming out from splinter_test test_splinter_print_diags, which is one of the test cases exercising print diagnostic code.

There are a few more draft PRs in the pipeline which are adding more such test cases invoking print code. The outputs from those tests, when added to /main will further clog up the test output files in CI, making browsing difficult.

So, this PR lays down an interim solution, introducing nascent support for log-message levels, which can be 'controlled' by existing env-var VERBOSE.

This way, we now have a solution for print-diagnostics test cases even while retaining the desired behaviour that most unit-tests are silent except for specialize unit-tests (misc_test, limitations_test) which want to print outputs from error messages, for example.

netlify · 2023-02-07T01:19:07Z

✅ Deploy Preview for splinterdb canceled.

Name	Link
🔨 Latest commit	`8035cc0`
🔍 Latest deploy log	https://app.netlify.com/sites/splinterdb/deploys/63e3b598b2a0520008ab0e7d

include/splinterdb/platform_linux/public_platform.h

tests/unit/btree_stress_test.c

gapisback · 2023-02-07T01:29:07Z

tests/unit/ctest.h

+ * Message verbosity levels:  Modeled on syslog's severity levels.
+ * See: https://en.wikipedia.org/wiki/Syslog
+ */
+typedef enum msg_level {


I considered the option of externalizing these by adding them to include/splinterdb/platform_linux/public_platform.h, but given that this is still preliminary code, and still cooking ... I figured it's best to scope these levels only to CTest code. For now.

Once we get a better handle on how all this plays out ... we could look into formalizing these levels in an external .h file.

tests/unit/unit_tests_common.c

tests/unit/ctest.h

gapisback · 2023-02-07T05:48:55Z

tests/unit/splinter_test.c

@@ -634,6 +634,8 @@ CTEST2(splinter, test_lookups)
 */
 CTEST2(splinter, test_splinter_print_diags)
 {
+   set_log_streams_for_tests(MSG_LEVEL_DEBUG);


This call will setup the output log handles if test-case is run with VERBOSE=7. This allows for manual inspection of the outputs while suppressing tons of output in CI (which invokes tests using VERBOSE=1).

rosenhouse

This code does not work the way I expect it too, I think there's a regression here. Try running
build/release/bin/unit/limitations_test without setting VERBOSE at all. Test on main vs on this branch. On main, the output is 14 lines showing only the tests passing. On this branch the output is 53 lines long and includes all the error messages that I'd expect to be supressed.

tests/unit/main.c

gapisback · 2023-02-07T06:05:59Z

You are right, @rosenhouse -- A change I made in a hurry to limitations_test.c had regressed behaviour. It's fixed now w/ the latest upload.

rosenhouse

Two things:

btree_stress_test is setting the wrong level.
Help output suggests setting VERBOSE=3 but that doesn't work.

tests/unit/ctest.h

rosenhouse · 2023-02-07T06:16:55Z

tests/unit/main.c

+      return MSG_LEVEL_DEBUG;
+   }
+   // Unknown verbosity level; fall-back to silent output mode.
+   return MSG_LEVEL_SILENT;


Is it much harder to use atoi or the modern secure equivalent? This "exact-match only with fallback" behavior is pretty confusing e.g. VERBOSE=3 is the same as VERBOSE=0.

I actually had coded it up to use atoi in an earlier version.

But then I felt VERBOSE=3 does nothing as that is an unsupported verbosity level. So, supporting that (or even allowing it thru this interface) appeared confusing by itself to me.

Which is why I went the route of only 'honoring' verbosity levels we know of now and support. The remaining unknown ones default (fall-back) to silent.

This way, one day when we do fill out the MSG_LEVEL_<> stream, the usage of VERBOSE=4 will properly mean and map to something supported.

tests/unit/main.c

tests/unit/btree_stress_test.c

gapisback · 2023-02-07T19:58:16Z

@rosenhouse -- I cleaned up the code / comments based on our discussion this morning. Have run some sanity tests to verify that the outputs are coming out 'as expected'. Just pushed a new commit.

Please take a final look and re-test to ensure that things are working as we expected / converged on.

gapisback · 2023-02-07T19:59:44Z

tests/unit/unit_tests_common.c

- * silent, redirecting output handles to /dev/null.
- *
- * Returns: Output file handles (out/error) if caller has requested for them.
+ * VERBOSE env var to opt-in.


You may want to review this edited prolog comment block ... for accuracy.

I think it is accurate, but perhaps incomplete. It would be good to call out some actionable instructions for unit test authors. For example, we could add something like:

Tests which exercise error paths in the library should first call this function with MSG_LEVEL_ERRORS, so that any error messages generated by the library are only shown when the test is run with VERBOSE >= 3.

Tests which cause the library to generate debug output (e.g. by printing internal data structures) should call this function with MSG_LEVEL_DEBUG, so that that output is only shown when the test is run with VERBOSE>=7.

rosenhouse · 2023-02-07T21:22:51Z

tests/unit/unit_tests_common.c

-                     "Or, the test may exercise print-diagnostic code.\n");
+      CTEST_LOG("Verbose mode on. This test may exercise an error case, so on"
+                " success it may print a message that appears to be an error."
+                " Or, the test may exercise print-diagnostic code.\n");


One thing I didn't consider when we discussed this before is that, now that we've combined these two functions together, if you run a non-error-exercising test with VERBOSE=3 you'll see this message, which is kind of noise since it is never true.

I think I'd be ok with either of the following "fixes":

Just shorten this message so it's less than 80 characters, so at least its not too much noise

Add a boolean argument to this function, something like bool may_print_errors, which would control whether or not this log line is shown. And then pass in true from limitations_test and such, but false otherwise.

@rosenhouse - I did a large'ish rework of all this handling and updated set_log_streams_for_tests() to a large extent. Lots has changed.

See this commit.

include/splinterdb/platform_linux/public_platform.h

rosenhouse

Fantastic. I just tested it out and it works exactly how I hoped. Thank you! I left a couple small suggestions, but overall it looks good.

tests/unit/main.c

rosenhouse · 2023-02-08T05:46:16Z

tests/unit/unit_tests_common.c

- * silent, redirecting output handles to /dev/null.
- *
- * Returns: Output file handles (out/error) if caller has requested for them.
+ * VERBOSE env var to opt-in.


I think it is accurate, but perhaps incomplete. It would be good to call out some actionable instructions for unit test authors. For example, we could add something like:

Tests which exercise error paths in the library should first call this function with MSG_LEVEL_ERRORS, so that any error messages generated by the library are only shown when the test is run with VERBOSE >= 3.

Tests which cause the library to generate debug output (e.g. by printing internal data structures) should call this function with MSG_LEVEL_DEBUG, so that that output is only shown when the test is run with VERBOSE>=7.

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

rosenhouse · 2023-02-08T18:57:37Z

I have applied the CI config changes here to our Concourse server, so the new VERBOSE: 3 level should be used along with this code the next time CI is triggered.

vmwclabot added the cla-not-required label Feb 7, 2023