test: log: Convert log_test from python to C

When rebasing this series I had to renumber all my log tests because
someone made another log test in the meantime. This involved updaing a
number in several places (C and python), and it wasn't checked by the
compiler. So I though "how hard could it be to just rewrite in C?" And
though it wasn't hard, it *was* tedious. Tests are numbered the same as
before to allow for easier review.

A note that if a test fails, everything after it will probably also fail.
This is because that test won't clean up its filters.  There's no easy way
to do the cleanup, except perhaps removing all filters in a wrapper
function.

Signed-off-by: Sean Anderson <seanga2@gmail.com>
This commit is contained in:
Sean Anderson 2020-10-27 19:55:27 -04:00 committed by Tom Rini
parent fe3b1a2d21
commit 62ef81891d
5 changed files with 260 additions and 300 deletions

View File

@ -105,9 +105,6 @@ static int do_log_rec(struct cmd_tbl *cmdtp, int flag, int argc,
static struct cmd_tbl log_sub[] = {
U_BOOT_CMD_MKENT(level, CONFIG_SYS_MAXARGS, 1, do_log_level, "", ""),
#if CONFIG_IS_ENABLED(LOG_TEST)
U_BOOT_CMD_MKENT(test, 2, 1, do_log_test, "", ""),
#endif
U_BOOT_CMD_MKENT(format, CONFIG_SYS_MAXARGS, 1, do_log_format, "", ""),
U_BOOT_CMD_MKENT(rec, CONFIG_SYS_MAXARGS, 1, do_log_rec, "", ""),
};
@ -133,9 +130,6 @@ static int do_log(struct cmd_tbl *cmdtp, int flag, int argc, char *const argv[])
#ifdef CONFIG_SYS_LONGHELP
static char log_help_text[] =
"level - get/set log level\n"
#if CONFIG_IS_ENABLED(LOG_TEST)
"log test - run log tests\n"
#endif
"log format <fmt> - set log output format. <fmt> is a string where\n"
"\teach letter indicates something that should be displayed:\n"
"\tc=category, l=level, F=file, L=line number, f=function, m=msg\n"

View File

@ -10,6 +10,8 @@
#include <test/test.h>
#define LOGF_TEST (BIT(LOGF_FUNC) | BIT(LOGF_MSG))
/* Declare a new logging test */
#define LOG_TEST(_name) UNIT_TEST(_name, 0, log_test)

View File

@ -9,12 +9,17 @@
#include <common.h>
#include <command.h>
#include <log.h>
#include <test/log.h>
#include <test/ut.h>
DECLARE_GLOBAL_DATA_PTR;
/* emit some sample log records in different ways, for testing */
static int log_run(enum uclass_id cat, const char *file)
static int do_log_run(int cat, const char *file)
{
int i;
gd->log_fmt = LOGF_TEST;
debug("debug\n");
for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
log(cat, i, "log %d\n", i);
@ -22,203 +27,268 @@ static int log_run(enum uclass_id cat, const char *file)
i);
}
gd->log_fmt = log_get_default_format();
return 0;
}
static int log_test(int testnum)
#define log_run_cat(cat) do_log_run(cat, "file")
#define log_run_file(file) do_log_run(UCLASS_SPI, file)
#define log_run() do_log_run(UCLASS_SPI, "file")
#define EXPECT_LOG BIT(0)
#define EXPECT_DIRECT BIT(1)
#define EXPECT_EXTRA BIT(2)
static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
int max)
{
int ret;
int i;
printf("test %d\n", testnum);
switch (testnum) {
case 0: {
/* Check a category filter using the first category */
enum log_category_t cat_list[] = {
log_uc_cat(UCLASS_MMC), log_uc_cat(UCLASS_SPI),
LOGC_NONE, LOGC_END
};
ret = log_add_filter("console", cat_list, LOGL_MAX, NULL);
if (ret < 0)
return ret;
log_run(UCLASS_MMC, "file");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 1: {
/* Check a category filter using the second category */
enum log_category_t cat_list[] = {
log_uc_cat(UCLASS_MMC), log_uc_cat(UCLASS_SPI), LOGC_END
};
ret = log_add_filter("console", cat_list, LOGL_MAX, NULL);
if (ret < 0)
return ret;
log_run(UCLASS_SPI, "file");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 2: {
/* Check a category filter that should block log entries */
enum log_category_t cat_list[] = {
log_uc_cat(UCLASS_MMC), LOGC_NONE, LOGC_END
};
ret = log_add_filter("console", cat_list, LOGL_MAX, NULL);
if (ret < 0)
return ret;
log_run(UCLASS_SPI, "file");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 3: {
/* Check a passing file filter */
ret = log_add_filter("console", NULL, LOGL_MAX, "file");
if (ret < 0)
return ret;
log_run(UCLASS_SPI, "file");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 4: {
/* Check a failing file filter */
ret = log_add_filter("console", NULL, LOGL_MAX, "file");
if (ret < 0)
return ret;
log_run(UCLASS_SPI, "file2");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 5: {
/* Check a passing file filter (second in list) */
ret = log_add_filter("console", NULL, LOGL_MAX, "file,file2");
if (ret < 0)
return ret;
log_run(UCLASS_SPI, "file2");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 6: {
/* Check a passing file filter */
ret = log_add_filter("console", NULL, LOGL_MAX,
"file,file2,log/log_test.c");
if (ret < 0)
return ret;
log_run(UCLASS_SPI, "file2");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 7: {
/* Check a log level filter */
ret = log_add_filter("console", NULL, LOGL_WARNING, NULL);
if (ret < 0)
return ret;
log_run(UCLASS_SPI, "file");
ret = log_remove_filter("console", ret);
if (ret < 0)
return ret;
break;
}
case 8: {
/* Check two filters, one of which passes everything */
int filt1, filt2;
ret = log_add_filter("console", NULL, LOGL_WARNING, NULL);
if (ret < 0)
return ret;
filt1 = ret;
ret = log_add_filter("console", NULL, LOGL_MAX, NULL);
if (ret < 0)
return ret;
filt2 = ret;
log_run(UCLASS_SPI, "file");
ret = log_remove_filter("console", filt1);
if (ret < 0)
return ret;
ret = log_remove_filter("console", filt2);
if (ret < 0)
return ret;
break;
}
case 9: {
/* Check three filters, which together pass everything */
int filt1, filt2, filt3;
ret = log_add_filter("console", NULL, LOGL_MAX, "file)");
if (ret < 0)
return ret;
filt1 = ret;
ret = log_add_filter("console", NULL, LOGL_MAX, "file2");
if (ret < 0)
return ret;
filt2 = ret;
ret = log_add_filter("console", NULL, LOGL_MAX,
"log/log_test.c");
if (ret < 0)
return ret;
filt3 = ret;
log_run(UCLASS_SPI, "file2");
ret = log_remove_filter("console", filt1);
if (ret < 0)
return ret;
ret = log_remove_filter("console", filt2);
if (ret < 0)
return ret;
ret = log_remove_filter("console", filt3);
if (ret < 0)
return ret;
break;
}
case 10: {
log_err("level %d\n", LOGL_EMERG);
log_err("level %d\n", LOGL_ALERT);
log_err("level %d\n", LOGL_CRIT);
log_err("level %d\n", LOGL_ERR);
log_warning("level %d\n", LOGL_WARNING);
log_notice("level %d\n", LOGL_NOTICE);
log_info("level %d\n", LOGL_INFO);
log_debug("level %d\n", LOGL_DEBUG);
log_content("level %d\n", LOGL_DEBUG_CONTENT);
log_io("level %d\n", LOGL_DEBUG_IO);
break;
}
case 11:
log_err("default\n");
ret = log_device_set_enable(LOG_GET_DRIVER(console), false);
log_err("disabled\n");
ret = log_device_set_enable(LOG_GET_DRIVER(console), true);
log_err("enabled\n");
break;
}
for (i = min; i <= max; i++) {
if (flags & EXPECT_LOG)
ut_assert_nextline("do_log_run() log %d", i);
if (flags & EXPECT_DIRECT)
ut_assert_nextline("func() _log %d", i);
}
if (flags & EXPECT_EXTRA)
for (; i <= LOGL_MAX ; i++)
ut_assert_nextline("func() _log %d", i);
ut_assert_console_end();
return 0;
}
int do_log_test(struct cmd_tbl *cmdtp, int flag, int argc, char *const argv[])
#define check_log_entries_flags_levels(flags, min, max) do {\
int ret = do_check_log_entries(uts, flags, min, max); \
if (ret) \
return ret; \
} while (0)
#define check_log_entries_flags(flags) \
check_log_entries_flags_levels(flags, LOGL_FIRST, _LOG_MAX_LEVEL)
#define check_log_entries() check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT)
#define check_log_entries_extra() \
check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_EXTRA)
#define check_log_entries_none() check_log_entries_flags(0)
/* Check a category filter using the first category */
int log_test_00(struct unit_test_state *uts)
{
enum log_category_t cat_list[] = {
log_uc_cat(UCLASS_MMC), log_uc_cat(UCLASS_SPI),
LOGC_NONE, LOGC_END
};
int filt;
filt = log_add_filter("console", cat_list, LOGL_MAX, NULL);
ut_assert(filt >= 0);
ut_assertok(console_record_reset_enable());
log_run_cat(UCLASS_MMC);
check_log_entries_extra();
ut_assertok(console_record_reset_enable());
log_run_cat(UCLASS_SPI);
check_log_entries_extra();
ut_assertok(log_remove_filter("console", filt));
return 0;
}
LOG_TEST_FLAGS(log_test_00, UT_TESTF_CONSOLE_REC);
/* Check a category filter that should block log entries */
int log_test_02(struct unit_test_state *uts)
{
enum log_category_t cat_list[] = {
log_uc_cat(UCLASS_MMC), LOGC_NONE, LOGC_END
};
int filt;
filt = log_add_filter("console", cat_list, LOGL_MAX, NULL);
ut_assert(filt >= 0);
ut_assertok(console_record_reset_enable());
log_run_cat(UCLASS_SPI);
check_log_entries_none();
ut_assertok(log_remove_filter("console", filt));
return 0;
}
LOG_TEST_FLAGS(log_test_02, UT_TESTF_CONSOLE_REC);
/* Check passing and failing file filters */
int log_test_03(struct unit_test_state *uts)
{
int filt;
filt = log_add_filter("console", NULL, LOGL_MAX, "file");
ut_assert(filt >= 0);
ut_assertok(console_record_reset_enable());
log_run_file("file");
check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA);
ut_assertok(console_record_reset_enable());
log_run_file("file2");
check_log_entries_none();
ut_assertok(log_remove_filter("console", filt));
return 0;
}
LOG_TEST_FLAGS(log_test_03, UT_TESTF_CONSOLE_REC);
/* Check a passing file filter (second in list) */
int log_test_05(struct unit_test_state *uts)
{
int filt;
filt = log_add_filter("console", NULL, LOGL_MAX, "file,file2");
ut_assert(filt >= 0);
ut_assertok(console_record_reset_enable());
log_run_file("file2");
check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA);
ut_assertok(log_remove_filter("console", filt));
return 0;
}
LOG_TEST_FLAGS(log_test_05, UT_TESTF_CONSOLE_REC);
/* Check a passing file filter (middle of list) */
int log_test_06(struct unit_test_state *uts)
{
int filt;
filt = log_add_filter("console", NULL, LOGL_MAX,
"file,file2,log/log_test.c");
ut_assert(filt >= 0);
ut_assertok(console_record_reset_enable());
log_run_file("file2");
check_log_entries_extra();
ut_assertok(log_remove_filter("console", filt));
return 0;
}
LOG_TEST_FLAGS(log_test_06, UT_TESTF_CONSOLE_REC);
/* Check a log level filter */
int log_test_07(struct unit_test_state *uts)
{
int filt;
filt = log_add_filter("console", NULL, LOGL_WARNING, NULL);
ut_assert(filt >= 0);
ut_assertok(console_record_reset_enable());
log_run();
check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT, LOGL_FIRST,
LOGL_WARNING);
ut_assertok(log_remove_filter("console", filt));
return 0;
}
LOG_TEST_FLAGS(log_test_07, UT_TESTF_CONSOLE_REC);
/* Check two filters, one of which passes everything */
int log_test_08(struct unit_test_state *uts)
{
int filt1, filt2;
filt1 = log_add_filter("console", NULL, LOGL_WARNING, NULL);
ut_assert(filt1 >= 0);
filt2 = log_add_filter("console", NULL, LOGL_MAX, NULL);
ut_assert(filt2 >= 0);
ut_assertok(console_record_reset_enable());
log_run();
check_log_entries_extra();
ut_assertok(log_remove_filter("console", filt1));
ut_assertok(log_remove_filter("console", filt2));
return 0;
}
LOG_TEST_FLAGS(log_test_08, UT_TESTF_CONSOLE_REC);
/* Check three filters, which together pass everything */
int log_test_09(struct unit_test_state *uts)
{
int filt1, filt2, filt3;
filt1 = log_add_filter("console", NULL, LOGL_MAX, "file)");
ut_assert(filt1 >= 0);
filt2 = log_add_filter("console", NULL, LOGL_MAX, "file2");
ut_assert(filt2 >= 0);
filt3 = log_add_filter("console", NULL, LOGL_MAX, "log/log_test.c");
ut_assert(filt3 >= 0);
ut_assertok(console_record_reset_enable());
log_run_file("file2");
check_log_entries_extra();
ut_assertok(log_remove_filter("console", filt1));
ut_assertok(log_remove_filter("console", filt2));
ut_assertok(log_remove_filter("console", filt3));
return 0;
}
LOG_TEST_FLAGS(log_test_09, UT_TESTF_CONSOLE_REC);
int do_log_test_10(struct unit_test_state *uts)
{
int i;
ut_assertok(console_record_reset_enable());
log_err("level %d\n", LOGL_EMERG);
log_err("level %d\n", LOGL_ALERT);
log_err("level %d\n", LOGL_CRIT);
log_err("level %d\n", LOGL_ERR);
log_warning("level %d\n", LOGL_WARNING);
log_notice("level %d\n", LOGL_NOTICE);
log_info("level %d\n", LOGL_INFO);
log_debug("level %d\n", LOGL_DEBUG);
log_content("level %d\n", LOGL_DEBUG_CONTENT);
log_io("level %d\n", LOGL_DEBUG_IO);
for (i = LOGL_EMERG; i <= _LOG_MAX_LEVEL; i++)
ut_assert_nextline("%s() level %d", __func__, i);
ut_assert_console_end();
return 0;
}
int log_test_10(struct unit_test_state *uts)
{
int testnum = 0;
int ret;
if (argc > 1)
testnum = simple_strtoul(argv[1], NULL, 10);
ret = log_test(testnum);
if (ret)
printf("Test failure (err=%d)\n", ret);
return ret ? CMD_RET_FAILURE : 0;
gd->log_fmt = LOGF_TEST;
ret = do_log_test_10(uts);
gd->log_fmt = log_get_default_format();
return ret;
}
LOG_TEST_FLAGS(log_test_10, UT_TESTF_CONSOLE_REC);
int do_log_test_11(struct unit_test_state *uts)
{
ut_assertok(console_record_reset_enable());
log_err("default\n");
ut_assert_nextline("%s() default", __func__);
ut_assertok(log_device_set_enable(LOG_GET_DRIVER(console), false));
log_err("disabled\n");
ut_assertok(log_device_set_enable(LOG_GET_DRIVER(console), true));
log_err("enabled\n");
ut_assert_nextline("%s() enabled", __func__);
ut_assert_console_end();
return 0;
}
int log_test_11(struct unit_test_state *uts)
{
int ret;
gd->log_fmt = LOGF_TEST;
ret = do_log_test_10(uts);
gd->log_fmt = log_get_default_format();
return ret;
}
LOG_TEST_FLAGS(log_test_11, UT_TESTF_CONSOLE_REC);

View File

@ -8,8 +8,6 @@
#ifndef __SYSLOG_TEST_H
#define __SYSLOG_TEST_H
#define LOGF_TEST (BIT(LOGF_FUNC) | BIT(LOGF_MSG))
/**
* struct sb_log_env - private data for sandbox ethernet driver
*

View File

@ -10,110 +10,6 @@ and checks that the output is correct.
import pytest
LOGL_FIRST, LOGL_WARNING, LOGL_INFO = (0, 4, 6)
@pytest.mark.buildconfigspec('cmd_log')
def test_log(u_boot_console):
"""Test that U-Boot logging works correctly."""
def check_log_entries(lines, mask, max_level=LOGL_INFO):
"""Check that the expected log records appear in the output
Args:
lines: iterator containing lines to check
mask: bit mask to select which lines to check for:
bit 0: standard log line
bit 1: _log line
max_level: maximum log level to expect in the output
"""
for i in range(max_level):
if mask & 1:
assert 'log_run() log %d' % i == next(lines)
if mask & 3:
assert 'func() _log %d' % i == next(lines)
def run_test(testnum):
"""Run a particular test number (the 'log test' command)
Args:
testnum: Test number to run
Returns:
iterator containing the lines output from the command
"""
output = u_boot_console.run_command('log format fm')
assert output == ''
with cons.log.section('basic'):
output = u_boot_console.run_command('log test %d' % testnum)
split = output.replace('\r', '').splitlines()
lines = iter(split)
assert 'test %d' % testnum == next(lines)
return lines
def test0():
lines = run_test(0)
check_log_entries(lines, 3)
def test1():
lines = run_test(1)
check_log_entries(lines, 3)
def test2():
lines = run_test(2)
def test3():
lines = run_test(3)
check_log_entries(lines, 2)
def test4():
lines = run_test(4)
assert next(lines, None) == None
def test5():
lines = run_test(5)
check_log_entries(lines, 2)
def test6():
lines = run_test(6)
check_log_entries(lines, 3)
def test7():
lines = run_test(7)
check_log_entries(lines, 3, LOGL_WARNING)
def test8():
lines = run_test(8)
check_log_entries(lines, 3)
def test9():
lines = run_test(9)
check_log_entries(lines, 3)
def test10():
lines = run_test(10)
for i in range(7):
assert 'log_test() level %d' % i == next(lines)
def test11():
"""Test use of log_device_set_enable()"""
lines = run_test(11)
assert 'log_test() default'
# disabled should not be displayed
assert 'log_test() enabled'
# TODO(sjg@chromium.org): Consider structuring this as separate tests
cons = u_boot_console
test0()
test1()
test2()
test3()
test4()
test5()
test6()
test7()
test8()
test9()
test10()
test11()
@pytest.mark.buildconfigspec('cmd_log')
def test_log_format(u_boot_console):
"""Test the 'log format' and 'log rec' commands"""