test: add --log option to display tests execution

When enabled (--log=1), shows test start, completion, and execution time.

Author: furszy

src/unit_test.c

@@ -26,6 +26,7 @@ static int parse_jobs_count(const char* key, const char* value, struct tf_framew
 static int parse_iterations(const char* key, const char* value, struct tf_framework* tf);
 static int parse_seed(const char* key, const char* value, struct tf_framework* tf);
 static int parse_target(const char* key, const char* value, struct tf_framework* tf);
+static int parse_logging(const char* key, const char* value, struct tf_framework* tf);
 
 /* Mapping table: key -> handler */
 typedef int (*ArgHandler)(const char* key, const char* value, struct tf_framework* tf);
@@ -46,6 +47,7 @@ static struct ArgMap arg_map[] = {
     { "j", parse_jobs_count }, { "jobs", parse_jobs_count },
     { "i", parse_iterations }, { "iterations", parse_iterations },
     { "seed", parse_seed },
+    { "log", parse_logging },
     { NULL, NULL } /* sentinel */
 };
 
@@ -87,6 +89,7 @@ static void help(void) {
     printf("    --seed=<hex>                         Set a specific RNG seed (default: random)\n");
     printf("    --target=<test name>, -t=<name>      Run a specific test (can be provided multiple times)\n");
     printf("    --target=<module name>, -t=<module>  Run all tests within a specific module (can be provided multiple times)\n");
+    printf("    --log=<0|1>                          Enable or disable test execution logging (default: 0 = disabled)\n");
     printf("\n");
     printf("Notes:\n");
     printf("    - All arguments must be provided in the form '--key=value', '-key=value' or '-k=value'.\n");
@@ -146,6 +149,12 @@ static int parse_seed(const char* key, const char* value, struct tf_framework* t
     return 0;
 }
 
+static int parse_logging(const char* key, const char* value, struct tf_framework* tf) {
+    UNUSED(key);
+    tf->args.logging = value && strcmp(value, "1") == 0;
+    return 0;
+}
+
 /* Strip up to two leading dashes */
 static const char* normalize_key(const char* arg, const char** err_msg) {
     const char* key;
@@ -248,18 +257,21 @@ static int read_args(int argc, char** argv, int start, struct tf_framework* tf)
     return 0;
 }
 
-static void run_test(const struct tf_test_entry* t) {
+static void run_test_log(const struct tf_test_entry* t) {
+    int64_t start_time = gettime_i64();
     printf("Running %s..\n", t->name);
     t->func();
-    printf("%s PASSED\n", t->name);
+    printf("Test %s PASSED (%.3f sec)\n", t->name, (double)(gettime_i64() - start_time) / 1000000);
 }
 
+static void run_test(const struct tf_test_entry* t) { t->func(); }
+
 /* Process tests in sequential order */
 static int run_sequential(struct tf_framework* tf) {
     int it;
     for (it = 0; it < tf->args.targets.size; it++) {
         const TestRef* index = &tf->args.targets.slots[it];
-        run_test(&tf->registry_modules[index->group].data[index->idx]);
+        tf->fn_run_test(&tf->registry_modules[index->group].data[index->idx]);
     }
     return EXIT_SUCCESS;
 }
@@ -297,7 +309,7 @@ static int run_concurrent(struct tf_framework* tf) {
             TestRef tref;
             close(pipes[it][1]); /* Close write end */
             while (read(pipes[it][0], &tref, sizeof(tref)) == sizeof(tref)) {
-                run_test(&tf->registry_modules[tref.group].data[tref.idx]);
+                tf->fn_run_test(&tf->registry_modules[tref.group].data[tref.idx]);
             }
             _exit(EXIT_SUCCESS); /* finish child process */
         } else {
@@ -346,6 +358,7 @@ static int tf_init(struct tf_framework* tf, int argc, char** argv)
     tf->args.help = 0;
     tf->args.targets.size = 0;
     tf->args.list_tests = 0;
+    tf->args.logging = 0;
 
     /* Disable buffering for stdout to improve reliability of getting
      * diagnostic information. Happens right at the start of main because
@@ -389,6 +402,7 @@ static int tf_init(struct tf_framework* tf, int argc, char** argv)
         }
     }
 
+    tf->fn_run_test = tf->args.logging ? run_test_log : run_test;
     return EXIT_SUCCESS;
 }
 
@@ -401,6 +415,12 @@ static int tf_run(struct tf_framework* tf) {
     int it;
     /* Initial test time */
     int64_t start_time = gettime_i64();
+    /* Verify 'tf_init' has been called */
+    if (!tf->fn_run_test) {
+        fprintf(stderr, "Error: No test runner set. You must call 'tf_init' first to initialize the framework "
+                        "or manually assign 'fn_run_test' before calling 'tf_run'.\n");
+        return EXIT_FAILURE;
+    }
 
     /* Populate targets with all tests if none were explicitly specified */
     run_all = tf->args.targets.size == 0;
@@ -419,6 +439,8 @@ static int tf_run(struct tf_framework* tf) {
         }
     }
 
+    if (!tf->args.logging) printf("Tests running silently. Use '-log=1' to enable detailed logging\n");
+
     /* Log configuration */
     print_args(&tf->args);
 
@@ -427,7 +449,7 @@ static int tf_run(struct tf_framework* tf) {
     /* is really only one test. */
     for (it = 0; tf->registry_no_rng && it < tf->registry_no_rng->size; it++) {
         if (run_all) { /* future: support filtering */
-            run_test(&tf->registry_no_rng->data[it]);
+            tf->fn_run_test(&tf->registry_no_rng->data[it]);
         }
     }
 

src/unit_test.h

@@ -61,6 +61,7 @@ struct tf_test_module {
 
 typedef int (*setup_ctx_fn)(void);
 typedef int (*teardown_fn)(void);
+typedef void (*run_test_fn)(const struct tf_test_entry*);
 
 /* Reference to a test in the registry. Group index and test index */
 typedef struct {
@@ -87,6 +88,8 @@ struct tf_args {
     int list_tests;
     /* Target tests indexes */
     struct Targets targets;
+    /* Enable test execution logging */
+    int logging;
 };
 
 /* --------------------------------------------------------- */
@@ -105,6 +108,8 @@ struct tf_framework {
     /* Specific context setup and teardown functions */
     setup_ctx_fn fn_setup;
     teardown_fn fn_teardown;
+    /* Test runner function (can be customized) */
+    run_test_fn fn_run_test;
 };
 
 /*