[PATCH v3 09/23] test: log: Convert log_test from python to C

[Sean Anderson <seanga2@gmail.com>]

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>
---

Changes in v3:
- New

 cmd/log.c                 |   6 -
 include/test/log.h        |   2 +
 test/log/log_test.c       | 446 ++++++++++++++++++++++----------------
 test/log/syslog_test.h    |   2 -
 test/py/tests/test_log.py | 104 ---------
 5 files changed, 260 insertions(+), 300 deletions(-)

diff --git a/cmd/log.c b/cmd/log.c
index 16a6ef7539..d20bfdf744 100644
--- a/cmd/log.c
+++ b/cmd/log.c
@@ -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"
diff --git a/include/test/log.h b/include/test/log.h
index c661cde75a..772e197806 100644
--- a/include/test/log.h
+++ b/include/test/log.h
@@ -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)
 
diff --git a/test/log/log_test.c b/test/log/log_test.c
index 6a60ff6be3..c5ca6dcb7a 100644
--- a/test/log/log_test.c
+++ b/test/log/log_test.c
@@ -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);
diff --git a/test/log/syslog_test.h b/test/log/syslog_test.h
index 1310257bfe..bfaa6daef8 100644
--- a/test/log/syslog_test.h
+++ b/test/log/syslog_test.h
@@ -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
  *
diff --git a/test/py/tests/test_log.py b/test/py/tests/test_log.py
index 275f9382d2..387b392ce9 100644
--- a/test/py/tests/test_log.py
+++ b/test/py/tests/test_log.py
@@ -10,110 +10,6 @@ and checks that the output is correct.
 
 import pytest
 
-LOGL_FIRST, LOGL_WARNING, LOGL_INFO = (0, 4, 6)
-
- at 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 at 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"""
-- 
2.28.0