Commit 2324257d authored by Mykola Lysenko's avatar Mykola Lysenko Committed by Andrii Nakryiko

selftests/bpf: Refactor prog_tests logging and test execution

This is a pre-req to add separate logging for each subtest in
test_progs.

Move all the mutable test data to the test_result struct.
Move per-test init/de-init into the run_one_test function.
Consolidate data aggregation and final log output in
calculate_and_print_summary function.
As a side effect, this patch fixes double counting of errors
for subtests and possible duplicate output of subtest log
on failures.

Also, add prog_tests_framework.c test to verify some of the
counting logic.

As part of verification, confirmed that number of reported
tests is the same before and after the change for both parallel
and sequential test execution.
Signed-off-by: default avatarMykola Lysenko <mykolal@fb.com>
Signed-off-by: default avatarAndrii Nakryiko <andrii@kernel.org>
Link: https://lore.kernel.org/bpf/20220418222507.1726259-1-mykolal@fb.com
parent 0fb53aab
......@@ -36,13 +36,13 @@ struct test_config {
void (*bpf_destroy)(void *);
};
enum test_state {
enum bpf_test_state {
_TS_INVALID,
TS_MODULE_LOAD,
TS_MODULE_LOAD_FAIL,
};
static _Atomic enum test_state state = _TS_INVALID;
static _Atomic enum bpf_test_state state = _TS_INVALID;
static int sys_finit_module(int fd, const char *param_values, int flags)
{
......
// SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
#include "test_progs.h"
#include "testing_helpers.h"
static void clear_test_state(struct test_state *state)
{
state->error_cnt = 0;
state->sub_succ_cnt = 0;
state->skip_cnt = 0;
}
void test_prog_tests_framework(void)
{
struct test_state *state = env.test_state;
/* in all the ASSERT calls below we need to return on the first
* error due to the fact that we are cleaning the test state after
* each dummy subtest
*/
/* test we properly count skipped tests with subtests */
if (test__start_subtest("test_good_subtest"))
test__end_subtest();
if (!ASSERT_EQ(state->skip_cnt, 0, "skip_cnt_check"))
return;
if (!ASSERT_EQ(state->error_cnt, 0, "error_cnt_check"))
return;
if (!ASSERT_EQ(state->subtest_num, 1, "subtest_num_check"))
return;
clear_test_state(state);
if (test__start_subtest("test_skip_subtest")) {
test__skip();
test__end_subtest();
}
if (test__start_subtest("test_skip_subtest")) {
test__skip();
test__end_subtest();
}
if (!ASSERT_EQ(state->skip_cnt, 2, "skip_cnt_check"))
return;
if (!ASSERT_EQ(state->subtest_num, 3, "subtest_num_check"))
return;
clear_test_state(state);
if (test__start_subtest("test_fail_subtest")) {
test__fail();
test__end_subtest();
}
if (!ASSERT_EQ(state->error_cnt, 1, "error_cnt_check"))
return;
if (!ASSERT_EQ(state->subtest_num, 4, "subtest_num_check"))
return;
clear_test_state(state);
}
......@@ -51,19 +51,8 @@ struct prog_test_def {
int test_num;
void (*run_test)(void);
void (*run_serial_test)(void);
bool force_log;
int error_cnt;
int skip_cnt;
int sub_succ_cnt;
bool should_run;
bool tested;
bool need_cgroup_cleanup;
char *subtest_name;
int subtest_num;
/* store counts before subtest started */
int old_error_cnt;
};
/* Override C runtime library's usleep() implementation to ensure nanosleep()
......@@ -141,35 +130,32 @@ static bool should_run_subtest(struct test_selector *sel,
return subtest_num < subtest_sel->num_set_len && subtest_sel->num_set[subtest_num];
}
static void dump_test_log(const struct prog_test_def *test, bool failed)
static void dump_test_log(const struct prog_test_def *test,
const struct test_state *test_state,
bool force_failed)
{
if (stdout == env.stdout)
return;
bool failed = test_state->error_cnt > 0 || force_failed;
/* worker always holds log */
if (env.worker_id != -1)
return;
fflush(stdout); /* exports env.log_buf & env.log_cnt */
fflush(stdout); /* exports test_state->log_buf & test_state->log_cnt */
fprintf(env.stdout, "#%-3d %s:%s\n",
test->test_num, test->test_name,
failed ? "FAIL" : (test_state->skip_cnt ? "SKIP" : "OK"));
if (env.verbosity > VERBOSE_NONE || test->force_log || failed) {
if (env.log_cnt) {
env.log_buf[env.log_cnt] = '\0';
fprintf(env.stdout, "%s", env.log_buf);
if (env.log_buf[env.log_cnt - 1] != '\n')
if (env.verbosity > VERBOSE_NONE || test_state->force_log || failed) {
if (test_state->log_cnt) {
test_state->log_buf[test_state->log_cnt] = '\0';
fprintf(env.stdout, "%s", test_state->log_buf);
if (test_state->log_buf[test_state->log_cnt - 1] != '\n')
fprintf(env.stdout, "\n");
}
}
}
static void skip_account(void)
{
if (env.test->skip_cnt) {
env.skip_cnt++;
env.test->skip_cnt = 0;
}
}
static void stdio_restore(void);
/* A bunch of tests set custom affinity per-thread and/or per-process. Reset
......@@ -219,72 +205,78 @@ static void restore_netns(void)
void test__end_subtest(void)
{
struct prog_test_def *test = env.test;
int sub_error_cnt = test->error_cnt - test->old_error_cnt;
dump_test_log(test, sub_error_cnt);
struct test_state *state = env.test_state;
int sub_error_cnt = state->error_cnt - state->old_error_cnt;
fprintf(stdout, "#%d/%d %s/%s:%s\n",
test->test_num, test->subtest_num, test->test_name, test->subtest_name,
sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
test->test_num, state->subtest_num, test->test_name, state->subtest_name,
sub_error_cnt ? "FAIL" : (state->subtest_skip_cnt ? "SKIP" : "OK"));
if (sub_error_cnt)
test->error_cnt++;
else if (test->skip_cnt == 0)
test->sub_succ_cnt++;
skip_account();
if (sub_error_cnt == 0) {
if (state->subtest_skip_cnt == 0) {
state->sub_succ_cnt++;
} else {
state->subtest_skip_cnt = 0;
state->skip_cnt++;
}
}
free(test->subtest_name);
test->subtest_name = NULL;
free(state->subtest_name);
state->subtest_name = NULL;
}
bool test__start_subtest(const char *subtest_name)
{
struct prog_test_def *test = env.test;
struct test_state *state = env.test_state;
if (test->subtest_name)
if (state->subtest_name)
test__end_subtest();
test->subtest_num++;
state->subtest_num++;
if (!subtest_name || !subtest_name[0]) {
fprintf(env.stderr,
"Subtest #%d didn't provide sub-test name!\n",
test->subtest_num);
state->subtest_num);
return false;
}
if (!should_run_subtest(&env.test_selector,
&env.subtest_selector,
test->subtest_num,
state->subtest_num,
test->test_name,
subtest_name))
return false;
test->subtest_name = strdup(subtest_name);
if (!test->subtest_name) {
state->subtest_name = strdup(subtest_name);
if (!state->subtest_name) {
fprintf(env.stderr,
"Subtest #%d: failed to copy subtest name!\n",
test->subtest_num);
state->subtest_num);
return false;
}
env.test->old_error_cnt = env.test->error_cnt;
state->old_error_cnt = state->error_cnt;
return true;
}
void test__force_log(void)
{
env.test->force_log = true;
env.test_state->force_log = true;
}
void test__skip(void)
{
env.test->skip_cnt++;
if (env.test_state->subtest_name)
env.test_state->subtest_skip_cnt++;
else
env.test_state->skip_cnt++;
}
void test__fail(void)
{
env.test->error_cnt++;
env.test_state->error_cnt++;
}
int test__join_cgroup(const char *path)
......@@ -517,8 +509,11 @@ static struct prog_test_def prog_test_defs[] = {
#include <prog_tests/tests.h>
#undef DEFINE_TEST
};
static const int prog_test_cnt = ARRAY_SIZE(prog_test_defs);
static struct test_state test_states[ARRAY_SIZE(prog_test_defs)];
const char *argp_program_version = "test_progs 0.1";
const char *argp_program_bug_address = "<bpf@vger.kernel.org>";
static const char argp_program_doc[] = "BPF selftests test runner";
......@@ -701,7 +696,7 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state)
return 0;
}
static void stdio_hijack(void)
static void stdio_hijack(char **log_buf, size_t *log_cnt)
{
#ifdef __GLIBC__
env.stdout = stdout;
......@@ -715,7 +710,7 @@ static void stdio_hijack(void)
/* stdout and stderr -> buffer */
fflush(stdout);
stdout = open_memstream(&env.log_buf, &env.log_cnt);
stdout = open_memstream(log_buf, log_cnt);
if (!stdout) {
stdout = env.stdout;
perror("open_memstream");
......@@ -818,7 +813,7 @@ void crash_handler(int signum)
sz = backtrace(bt, ARRAY_SIZE(bt));
if (env.test)
dump_test_log(env.test, true);
dump_test_log(env.test, env.test_state, true);
if (env.stdout)
stdio_restore();
if (env.worker_id != -1)
......@@ -840,17 +835,6 @@ static int current_test_idx;
static pthread_mutex_t current_test_lock;
static pthread_mutex_t stdout_output_lock;
struct test_result {
int error_cnt;
int skip_cnt;
int sub_succ_cnt;
size_t log_cnt;
char *log_buf;
};
static struct test_result test_results[ARRAY_SIZE(prog_test_defs)];
static inline const char *str_msg(const struct msg *msg, char *buf)
{
switch (msg->type) {
......@@ -904,8 +888,12 @@ static int recv_message(int sock, struct msg *msg)
static void run_one_test(int test_num)
{
struct prog_test_def *test = &prog_test_defs[test_num];
struct test_state *state = &test_states[test_num];
env.test = test;
env.test_state = state;
stdio_hijack(&state->log_buf, &state->log_cnt);
if (test->run_test)
test->run_test();
......@@ -913,17 +901,19 @@ static void run_one_test(int test_num)
test->run_serial_test();
/* ensure last sub-test is finalized properly */
if (test->subtest_name)
if (state->subtest_name)
test__end_subtest();
test->tested = true;
state->tested = true;
dump_test_log(test, test->error_cnt);
dump_test_log(test, state, false);
reset_affinity();
restore_netns();
if (test->need_cgroup_cleanup)
cleanup_cgroup_environment();
stdio_restore();
}
struct dispatch_data {
......@@ -942,7 +932,7 @@ static void *dispatch_thread(void *ctx)
while (true) {
int test_to_run = -1;
struct prog_test_def *test;
struct test_result *result;
struct test_state *state;
/* grab a test */
{
......@@ -989,16 +979,15 @@ static void *dispatch_thread(void *ctx)
if (test_to_run != msg_test_done.test_done.test_num)
goto error;
test->tested = true;
result = &test_results[test_to_run];
result->error_cnt = msg_test_done.test_done.error_cnt;
result->skip_cnt = msg_test_done.test_done.skip_cnt;
result->sub_succ_cnt = msg_test_done.test_done.sub_succ_cnt;
state = &test_states[test_to_run];
state->tested = true;
state->error_cnt = msg_test_done.test_done.error_cnt;
state->skip_cnt = msg_test_done.test_done.skip_cnt;
state->sub_succ_cnt = msg_test_done.test_done.sub_succ_cnt;
/* collect all logs */
if (msg_test_done.test_done.have_log) {
log_fp = open_memstream(&result->log_buf, &result->log_cnt);
log_fp = open_memstream(&state->log_buf, &state->log_cnt);
if (!log_fp)
goto error;
......@@ -1017,25 +1006,11 @@ static void *dispatch_thread(void *ctx)
fclose(log_fp);
log_fp = NULL;
}
/* output log */
{
pthread_mutex_lock(&stdout_output_lock);
if (result->log_cnt) {
result->log_buf[result->log_cnt] = '\0';
fprintf(stdout, "%s", result->log_buf);
if (result->log_buf[result->log_cnt - 1] != '\n')
fprintf(stdout, "\n");
}
fprintf(stdout, "#%d %s:%s\n",
test->test_num, test->test_name,
result->error_cnt ? "FAIL" : (result->skip_cnt ? "SKIP" : "OK"));
pthread_mutex_unlock(&stdout_output_lock);
}
} /* wait for test done */
pthread_mutex_lock(&stdout_output_lock);
dump_test_log(test, state, false);
pthread_mutex_unlock(&stdout_output_lock);
} /* while (true) */
error:
if (env.debug)
......@@ -1057,38 +1032,50 @@ static void *dispatch_thread(void *ctx)
return NULL;
}
static void print_all_error_logs(void)
static void calculate_summary_and_print_errors(struct test_env *env)
{
int i;
int succ_cnt = 0, fail_cnt = 0, sub_succ_cnt = 0, skip_cnt = 0;
if (env.fail_cnt)
fprintf(stdout, "\nAll error logs:\n");
for (i = 0; i < prog_test_cnt; i++) {
struct test_state *state = &test_states[i];
if (!state->tested)
continue;
sub_succ_cnt += state->sub_succ_cnt;
skip_cnt += state->skip_cnt;
if (state->error_cnt)
fail_cnt++;
else
succ_cnt++;
}
if (fail_cnt)
printf("\nAll error logs:\n");
/* print error logs again */
for (i = 0; i < prog_test_cnt; i++) {
struct prog_test_def *test;
struct test_result *result;
test = &prog_test_defs[i];
result = &test_results[i];
struct prog_test_def *test = &prog_test_defs[i];
struct test_state *state = &test_states[i];
if (!test->tested || !result->error_cnt)
if (!state->tested || !state->error_cnt)
continue;
fprintf(stdout, "\n#%d %s:%s\n",
test->test_num, test->test_name,
result->error_cnt ? "FAIL" : (result->skip_cnt ? "SKIP" : "OK"));
if (result->log_cnt) {
result->log_buf[result->log_cnt] = '\0';
fprintf(stdout, "%s", result->log_buf);
if (result->log_buf[result->log_cnt - 1] != '\n')
fprintf(stdout, "\n");
}
dump_test_log(test, state, true);
}
printf("Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
succ_cnt, sub_succ_cnt, skip_cnt, fail_cnt);
env->succ_cnt = succ_cnt;
env->sub_succ_cnt = sub_succ_cnt;
env->fail_cnt = fail_cnt;
env->skip_cnt = skip_cnt;
}
static int server_main(void)
static void server_main(void)
{
pthread_t *dispatcher_threads;
struct dispatch_data *data;
......@@ -1144,60 +1131,18 @@ static int server_main(void)
for (int i = 0; i < prog_test_cnt; i++) {
struct prog_test_def *test = &prog_test_defs[i];
struct test_result *result = &test_results[i];
if (!test->should_run || !test->run_serial_test)
continue;
stdio_hijack();
run_one_test(i);
stdio_restore();
if (env.log_buf) {
result->log_cnt = env.log_cnt;
result->log_buf = strdup(env.log_buf);
free(env.log_buf);
env.log_buf = NULL;
env.log_cnt = 0;
}
restore_netns();
fprintf(stdout, "#%d %s:%s\n",
test->test_num, test->test_name,
test->error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
result->error_cnt = test->error_cnt;
result->skip_cnt = test->skip_cnt;
result->sub_succ_cnt = test->sub_succ_cnt;
}
/* generate summary */
fflush(stderr);
fflush(stdout);
for (i = 0; i < prog_test_cnt; i++) {
struct prog_test_def *current_test;
struct test_result *result;
current_test = &prog_test_defs[i];
result = &test_results[i];
if (!current_test->tested)
continue;
env.succ_cnt += result->error_cnt ? 0 : 1;
env.skip_cnt += result->skip_cnt;
if (result->error_cnt)
env.fail_cnt++;
env.sub_succ_cnt += result->sub_succ_cnt;
}
print_all_error_logs();
fprintf(stdout, "Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
env.succ_cnt, env.sub_succ_cnt, env.skip_cnt, env.fail_cnt);
calculate_summary_and_print_errors(&env);
/* reap all workers */
for (i = 0; i < env.workers; i++) {
......@@ -1207,8 +1152,6 @@ static int server_main(void)
if (pid != env.worker_pids[i])
perror("Unable to reap worker");
}
return 0;
}
static int worker_main(int sock)
......@@ -1229,35 +1172,29 @@ static int worker_main(int sock)
env.worker_id);
goto out;
case MSG_DO_TEST: {
int test_to_run;
struct prog_test_def *test;
int test_to_run = msg.do_test.test_num;
struct prog_test_def *test = &prog_test_defs[test_to_run];
struct test_state *state = &test_states[test_to_run];
struct msg msg_done;
test_to_run = msg.do_test.test_num;
test = &prog_test_defs[test_to_run];
if (env.debug)
fprintf(stderr, "[%d]: #%d:%s running.\n",
env.worker_id,
test_to_run + 1,
test->test_name);
stdio_hijack();
run_one_test(test_to_run);
stdio_restore();
memset(&msg_done, 0, sizeof(msg_done));
msg_done.type = MSG_TEST_DONE;
msg_done.test_done.test_num = test_to_run;
msg_done.test_done.error_cnt = test->error_cnt;
msg_done.test_done.skip_cnt = test->skip_cnt;
msg_done.test_done.sub_succ_cnt = test->sub_succ_cnt;
msg_done.test_done.error_cnt = state->error_cnt;
msg_done.test_done.skip_cnt = state->skip_cnt;
msg_done.test_done.sub_succ_cnt = state->sub_succ_cnt;
msg_done.test_done.have_log = false;
if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
if (env.log_cnt)
if (env.verbosity > VERBOSE_NONE || state->force_log || state->error_cnt) {
if (state->log_cnt)
msg_done.test_done.have_log = true;
}
if (send_message(sock, &msg_done) < 0) {
......@@ -1270,8 +1207,8 @@ static int worker_main(int sock)
char *src;
size_t slen;
src = env.log_buf;
slen = env.log_cnt;
src = state->log_buf;
slen = state->log_cnt;
while (slen) {
struct msg msg_log;
char *dest;
......@@ -1291,10 +1228,10 @@ static int worker_main(int sock)
assert(send_message(sock, &msg_log) >= 0);
}
}
if (env.log_buf) {
free(env.log_buf);
env.log_buf = NULL;
env.log_cnt = 0;
if (state->log_buf) {
free(state->log_buf);
state->log_buf = NULL;
state->log_cnt = 0;
}
if (env.debug)
fprintf(stderr, "[%d]: #%d:%s done.\n",
......@@ -1425,7 +1362,6 @@ int main(int argc, char **argv)
for (i = 0; i < prog_test_cnt; i++) {
struct prog_test_def *test = &prog_test_defs[i];
struct test_result *result;
if (!test->should_run)
continue;
......@@ -1441,34 +1377,7 @@ int main(int argc, char **argv)
continue;
}
stdio_hijack();
run_one_test(i);
stdio_restore();
fprintf(env.stdout, "#%d %s:%s\n",
test->test_num, test->test_name,
test->error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
result = &test_results[i];
result->error_cnt = test->error_cnt;
if (env.log_buf) {
result->log_buf = strdup(env.log_buf);
result->log_cnt = env.log_cnt;
free(env.log_buf);
env.log_buf = NULL;
env.log_cnt = 0;
}
if (test->error_cnt)
env.fail_cnt++;
else
env.succ_cnt++;
skip_account();
env.sub_succ_cnt += test->sub_succ_cnt;
}
if (env.get_test_cnt) {
......@@ -1479,10 +1388,7 @@ int main(int argc, char **argv)
if (env.list_test_names)
goto out;
print_all_error_logs();
fprintf(stdout, "Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
env.succ_cnt, env.sub_succ_cnt, env.skip_cnt, env.fail_cnt);
calculate_summary_and_print_errors(&env);
close(env.saved_netns_fd);
out:
......
......@@ -64,6 +64,25 @@ struct test_selector {
int num_set_len;
};
struct test_state {
bool tested;
bool force_log;
int error_cnt;
int skip_cnt;
int subtest_skip_cnt;
int sub_succ_cnt;
char *subtest_name;
int subtest_num;
/* store counts before subtest started */
int old_error_cnt;
size_t log_cnt;
char *log_buf;
};
struct test_env {
struct test_selector test_selector;
struct test_selector subtest_selector;
......@@ -76,12 +95,11 @@ struct test_env {
bool get_test_cnt;
bool list_test_names;
struct prog_test_def *test; /* current running tests */
struct prog_test_def *test; /* current running test */
struct test_state *test_state; /* current running test result */
FILE *stdout;
FILE *stderr;
char *log_buf;
size_t log_cnt;
int nr_cpus;
int succ_cnt; /* successful tests */
......@@ -126,11 +144,12 @@ struct msg {
extern struct test_env env;
extern void test__force_log();
extern bool test__start_subtest(const char *name);
extern void test__skip(void);
extern void test__fail(void);
extern int test__join_cgroup(const char *path);
void test__force_log(void);
bool test__start_subtest(const char *name);
void test__end_subtest(void);
void test__skip(void);
void test__fail(void);
int test__join_cgroup(const char *path);
#define PRINT_FAIL(format...) \
({ \
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment