[PATCH 0/3] log: enable filtering on functions
Up to now we could only use log level, category, and file for filtering.
In the UEFI sub-system event handling functions which are called at a very high frequency are in the same files as other functions of interest. Filtering on file level is too coarse for generating useful debug output.
Allow filtering on a list of functions and add unit tests.
(Resending as mail did not reach the U-Boot list.)
Heinrich Schuchardt (3): log: make log_has_file() static log: enable filtering on functions test/log: test function filters
cmd/log.c | 42 ++++++++++++----------- common/log.c | 33 ++++++++++++++---- include/log.h | 17 ++-------- test/log/log_filter.c | 1 - test/log/log_test.c | 78 +++++++++++++++++++++++++++++++++---------- 5 files changed, 112 insertions(+), 59 deletions(-)
When logging running an image, e.g. `bootefi hello` the indent is not correctly reset.
Signed-off-by: Heinrich Schuchardt heinrich.schuchardt@canonical.com --- include/efi_loader.h | 33 ++++++++++++++++++++++----------- lib/efi_loader/efi_boottime.c | 7 +++---- 2 files changed, 25 insertions(+), 15 deletions(-)
diff --git a/lib/efi_loader/efi_boottime.c b/lib/efi_loader/efi_boottime.c index 9f51db90f33..95d416adf9d 100644 --- a/lib/efi_loader/efi_boottime.c +++ b/lib/efi_loader/efi_boottime.c @@ -3258,11 +3258,10 @@ efi_status_t EFIAPI efi_start_image(efi_handle_t image_handle, * To get ready to call EFI_EXIT below we have to execute the * missed out steps of EFI_CALL. */ - assert(__efi_entry_check()); - EFI_PRINT("%lu returned by started image\n", - (unsigned long)((uintptr_t)exit_status & - ~EFI_ERROR_MASK)); + EFI_RETURN(exit_status); + current_image = parent_image; + return EFI_EXIT(exit_status); }
Function log_has_file() is not used externally. Make it static.
Rename the function to log_has_member() as we can reuse for filtering other strings.
Signed-off-by: Heinrich Schuchardt heinrich.schuchardt@canonical.com --- common/log.c | 20 ++++++++++++++------ include/log.h | 12 ------------ 2 files changed, 14 insertions(+), 18 deletions(-)
diff --git a/common/log.c b/common/log.c index c9fe35230d6..b2b5f3c81ba 100644 --- a/common/log.c +++ b/common/log.c @@ -130,17 +130,25 @@ bool log_has_cat(enum log_category_t cat_list[], enum log_category_t cat) return false; }
-bool log_has_file(const char *file_list, const char *file) +/** + * log_has_member() - check if a string is in a comma separated list + * + * @list: Comma separated list of strings + * @member: String to find + * + * Return: ``true`` if @member is in @list, else ``false`` + */ +static bool log_has_member(const char *list, const char *member) { - int file_len = strlen(file); + int member_len = strlen(member); const char *s, *p; int substr_len;
- for (s = file_list; *s; s = p + (*p != '\0')) { + for (s = list; *s; s = p + (*p != '\0')) { p = strchrnul(s, ','); substr_len = p - s; - if (file_len >= substr_len && - !strncmp(file + file_len - substr_len, s, substr_len)) + if (member_len >= substr_len && + !strncmp(member + member_len - substr_len, s, substr_len)) return true; }
@@ -181,7 +189,7 @@ static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec) continue;
if (filt->file_list && - !log_has_file(filt->file_list, rec->file)) + !log_has_member(filt->file_list, rec->file)) continue;
if (filt->flags & LOGFF_DENY) diff --git a/include/log.h b/include/log.h index 4f6d6a2c2cf..3f9023ae0d2 100644 --- a/include/log.h +++ b/include/log.h @@ -571,18 +571,6 @@ struct log_device *log_device_find_by_name(const char *drv_name); */ bool log_has_cat(enum log_category_t cat_list[], enum log_category_t cat);
-/** - * log_has_file() - check if a file is with a list - * - * @file_list: List of files to check, separated by comma - * @file: File to check for. This string is matched against the end of each - * file in the list, i.e. ignoring any preceding path. The list is - * intended to consist of relative pathnames, e.g. common/main.c,cmd/log.c - * - * Return: ``true`` if @file is in @file_list, else ``false`` - */ -bool log_has_file(const char *file_list, const char *file); - /* Log format flags (bit numbers) for gd->log_fmt. See log_fmt_chars */ enum log_fmt { LOGF_CAT = 0,
Up to now we could only use log level, category, and file for filtering. Allow filtering on a list of functions.
Signed-off-by: Heinrich Schuchardt heinrich.schuchardt@canonical.com --- cmd/log.c | 42 ++++++++++++++++++++++-------------------- common/log.c | 13 ++++++++++++- include/log.h | 5 +++-- test/log/log_filter.c | 1 - test/log/log_test.c | 10 +++++----- 5 files changed, 42 insertions(+), 29 deletions(-)
diff --git a/cmd/log.c b/cmd/log.c index 519ec76f3b5..64add6d8b5a 100644 --- a/cmd/log.c +++ b/cmd/log.c @@ -115,30 +115,27 @@ static int do_log_filter_list(struct cmd_tbl *cmdtp, int flag, int argc, return CMD_RET_FAILURE; }
- /* <3> < 6 > <2+1 + 7 > < 16 > < unbounded... */ - printf("num policy level categories files\n"); list_for_each_entry(filt, &ldev->filter_head, sibling_node) { - printf("%3d %6.6s %s %-7.7s ", filt->filter_num, - filt->flags & LOGFF_DENY ? "deny" : "allow", + printf("%-3d: %s %s %s\n", filt->filter_num, + filt->flags & LOGFF_DENY ? "DENY" : "ALLOW", filt->flags & LOGFF_LEVEL_MIN ? ">=" : "<=", log_get_level_name(filt->level));
if (filt->flags & LOGFF_HAS_CAT) { - int i; - - if (filt->cat_list[0] != LOGC_END) - printf("%16.16s %s\n", - log_get_cat_name(filt->cat_list[0]), - filt->file_list ? filt->file_list : ""); - - for (i = 1; i < LOGF_MAX_CATEGORIES && - filt->cat_list[i] != LOGC_END; i++) - printf("%21c %16.16s\n", ' ', + printf(" Categories:"); + for (int i = 0; + i < LOGF_MAX_CATEGORIES && + filt->cat_list[i] != LOGC_END; + ++i) { + printf(" %s", log_get_cat_name(filt->cat_list[i])); - } else { - printf("%16c %s\n", ' ', - filt->file_list ? filt->file_list : ""); + } + printf("\n"); } + if (filt->file_list) + printf(" Files: %s\n", filt->file_list); + if (filt->func_list) + printf(" Functions: %s\n", filt->func_list); }
return CMD_RET_SUCCESS; @@ -151,6 +148,7 @@ static int do_log_filter_add(struct cmd_tbl *cmdtp, int flag, int argc, bool print_num = false; bool type_set = false; char *file_list = NULL; + char *func_list = NULL; const char *drv_name = "console"; int opt, err; int cat_count = 0; @@ -160,7 +158,7 @@ static int do_log_filter_add(struct cmd_tbl *cmdtp, int flag, int argc, struct getopt_state gs;
getopt_init_state(&gs); - while ((opt = getopt(&gs, argc, argv, "Ac:d:Df:l:L:p")) > 0) { + while ((opt = getopt(&gs, argc, argv, "Ac:d:Df:F:l:L:p")) > 0) { switch (opt) { case 'A': #define do_type() do { \ @@ -199,6 +197,9 @@ static int do_log_filter_add(struct cmd_tbl *cmdtp, int flag, int argc, case 'f': file_list = gs.arg; break; + case 'F': + func_list = gs.arg; + break; case 'l': #define do_level() do { \ if (level_set) { \ @@ -229,7 +230,7 @@ static int do_log_filter_add(struct cmd_tbl *cmdtp, int flag, int argc,
cat_list[cat_count] = LOGC_END; err = log_add_filter_flags(drv_name, cat_count ? cat_list : NULL, level, - file_list, flags); + file_list, func_list, flags); if (err < 0) { printf("Could not add filter (err = %d)\n", err); return CMD_RET_FAILURE; @@ -388,7 +389,8 @@ U_BOOT_LONGHELP(log, "\t-d <driver> - Specify the log driver to add the filter to; defaults\n" "\t to console\n" "\t-D - Deny messages matching this filter; mutually exclusive with -A\n" - "\t-f <files_list> - A comma-separated list of files to match\n" + "\t-f <file_list> - A comma-separated list of files to match\n" + "\t-F <func_list> - A comma-separated list of functions to match\n" "\t-l <level> - Match log levels less than or equal to <level>;\n" "\t mutually-exclusive with -L\n" "\t-L <level> - Match log levels greather than or equal to <level>;\n" diff --git a/common/log.c b/common/log.c index b2b5f3c81ba..b75e404420b 100644 --- a/common/log.c +++ b/common/log.c @@ -192,6 +192,10 @@ static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec) !log_has_member(filt->file_list, rec->file)) continue;
+ if (filt->func_list && + !log_has_member(filt->func_list, rec->func)) + continue; + if (filt->flags & LOGFF_DENY) return false; else @@ -329,7 +333,7 @@ int _log_buffer(enum log_category_t cat, enum log_level_t level,
int log_add_filter_flags(const char *drv_name, enum log_category_t cat_list[], enum log_level_t level, const char *file_list, - int flags) + const char *func_list, int flags) { struct log_filter *filt; struct log_device *ldev; @@ -364,6 +368,13 @@ int log_add_filter_flags(const char *drv_name, enum log_category_t cat_list[], goto err; } } + if (func_list) { + filt->func_list = strdup(func_list); + if (!filt->func_list) { + ret = -ENOMEM; + goto err; + } + } filt->filter_num = ldev->next_filter_num++; /* Add deny filters to the beginning of the list */ if (flags & LOGFF_DENY) diff --git a/include/log.h b/include/log.h index 3f9023ae0d2..7d8d10c1fb9 100644 --- a/include/log.h +++ b/include/log.h @@ -508,6 +508,7 @@ struct log_filter { enum log_category_t cat_list[LOGF_MAX_CATEGORIES]; enum log_level_t level; const char *file_list; + const char *func_list; struct list_head sibling_node; };
@@ -605,7 +606,7 @@ int do_log_test(struct cmd_tbl *cmdtp, int flag, int argc, char *const argv[]); */ int log_add_filter_flags(const char *drv_name, enum log_category_t cat_list[], enum log_level_t level, const char *file_list, - int flags); + const char *func_list, int flags);
/** * log_add_filter() - Add a new filter to a log device @@ -628,7 +629,7 @@ static inline int log_add_filter(const char *drv_name, const char *file_list) { return log_add_filter_flags(drv_name, cat_list, max_level, file_list, - 0); + NULL, 0); }
/** diff --git a/test/log/log_filter.c b/test/log/log_filter.c index d36e9d9714e..8622dcf2913 100644 --- a/test/log/log_filter.c +++ b/test/log/log_filter.c @@ -39,7 +39,6 @@ static int log_test_filter(struct unit_test_state *uts)
#define create_filter(args, filter_num) do {\ ut_assertok(run_command("log filter-add -p " args, 0)); \ - ut_assert_skipline(); \ ut_assertok(strict_strtoul(uts->actual_str, 10, &(filter_num))); \ ut_assert_console_end(); \ } while (0) diff --git a/test/log/log_test.c b/test/log/log_test.c index 1c89df4ef18..8686b1cbef3 100644 --- a/test/log/log_test.c +++ b/test/log/log_test.c @@ -320,7 +320,7 @@ int log_test_cat_deny(struct unit_test_state *uts) filt1 = log_add_filter("console", cat_list, LOGL_MAX, NULL); ut_assert(filt1 >= 0); filt2 = log_add_filter_flags("console", cat_list, LOGL_MAX, NULL, - LOGFF_DENY); + NULL, LOGFF_DENY); ut_assert(filt2 >= 0);
log_run_cat(UCLASS_SPI); @@ -340,7 +340,7 @@ int log_test_file_deny(struct unit_test_state *uts) filt1 = log_add_filter("console", NULL, LOGL_MAX, "file"); ut_assert(filt1 >= 0); filt2 = log_add_filter_flags("console", NULL, LOGL_MAX, "file", - LOGFF_DENY); + NULL, LOGFF_DENY); ut_assert(filt2 >= 0);
log_run_file("file"); @@ -360,7 +360,7 @@ int log_test_level_deny(struct unit_test_state *uts) filt1 = log_add_filter("console", NULL, LOGL_INFO, NULL); ut_assert(filt1 >= 0); filt2 = log_add_filter_flags("console", NULL, LOGL_WARNING, NULL, - LOGFF_DENY); + NULL, LOGFF_DENY); ut_assert(filt2 >= 0);
log_run(); @@ -380,10 +380,10 @@ int log_test_min(struct unit_test_state *uts) int filt1, filt2;
filt1 = log_add_filter_flags("console", NULL, LOGL_WARNING, NULL, - LOGFF_LEVEL_MIN); + NULL, LOGFF_LEVEL_MIN); ut_assert(filt1 >= 0); filt2 = log_add_filter_flags("console", NULL, LOGL_INFO, NULL, - LOGFF_DENY | LOGFF_LEVEL_MIN); + NULL, LOGFF_DENY | LOGFF_LEVEL_MIN); ut_assert(filt2 >= 0);
log_run();
Add unit tests for function filters.
Signed-off-by: Heinrich Schuchardt heinrich.schuchardt@canonical.com --- test/log/log_test.c | 68 +++++++++++++++++++++++++++++++++++++-------- 1 file changed, 56 insertions(+), 12 deletions(-)
diff --git a/test/log/log_test.c b/test/log/log_test.c index 8686b1cbef3..00b442252f0 100644 --- a/test/log/log_test.c +++ b/test/log/log_test.c @@ -15,7 +15,8 @@ DECLARE_GLOBAL_DATA_PTR;
/* emit some sample log records in different ways, for testing */ -static int do_log_run(struct unit_test_state *uts, int cat, const char *file) +static int do_log_run(struct unit_test_state *uts, int cat, const char *file, + const char *func) { int i; int ret, expected_ret; @@ -30,13 +31,13 @@ static int do_log_run(struct unit_test_state *uts, int cat, const char *file) for (i = LOGL_FIRST; i < LOGL_COUNT; i++) { log(cat, i, "log %d\n", i); ret = _log(log_uc_cat(cat), i, file, 100 + i, - "func", "_log %d\n", i); + func, "_log %d\n", i); ut_asserteq(ret, expected_ret); } /* test with LOGL_COUNT flag */ for (i = LOGL_FIRST; i < LOGL_COUNT; i++) { ret = _log(log_uc_cat(cat), i | LOGL_FORCE_DEBUG, file, 100 + i, - "func", "_log force %d\n", i); + func, "_log force %d\n", i); ut_asserteq(ret, expected_ret); }
@@ -44,9 +45,10 @@ static int do_log_run(struct unit_test_state *uts, int cat, const char *file) return 0; }
-#define log_run_cat(cat) do_log_run(uts, cat, "file") -#define log_run_file(file) do_log_run(uts, UCLASS_SPI, file) -#define log_run() do_log_run(uts, UCLASS_SPI, "file") +#define log_run_cat(cat) do_log_run(uts, cat, "file", "func") +#define log_run_file(file) do_log_run(uts, UCLASS_SPI, file, "func") +#define log_run_func(func) do_log_run(uts, UCLASS_SPI, "file", func) +#define log_run() do_log_run(uts, UCLASS_SPI, "file", "func")
#define EXPECT_LOG BIT(0) #define EXPECT_DIRECT BIT(1) @@ -55,7 +57,7 @@ static int do_log_run(struct unit_test_state *uts, int cat, const char *file) #define EXPECT_DEBUG BIT(4)
static int do_check_log_entries(struct unit_test_state *uts, int flags, int min, - int max) + int max, const char *func) { int i;
@@ -63,7 +65,8 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min, if (flags & EXPECT_LOG) ut_assert_nextline(" do_log_run() log %d", i); if (flags & EXPECT_DIRECT) - ut_assert_nextline(" func() _log %d", i); + ut_assert_nextline(" %s() _log %d", func, + i); if (flags & EXPECT_DEBUG) { ut_assert_nextline("log %d", i); ut_assert_nextline("_log %d", i); @@ -71,12 +74,13 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min, } if (flags & EXPECT_EXTRA) for (; i <= LOGL_MAX ; i++) - ut_assert_nextline(" func() _log %d", i); + ut_assert_nextline(" %s() _log %d", func, + i);
for (i = LOGL_FIRST; i < LOGL_COUNT; i++) { if (flags & EXPECT_FORCE) - ut_assert_nextline(" func() _log force %d", - i); + ut_assert_nextline(" %s() _log force %d", + func, i); if (flags & EXPECT_DEBUG) ut_assert_nextline("_log force %d", i); } @@ -86,7 +90,7 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min, }
#define check_log_entries_flags_levels(flags, min, max) do {\ - int ret = do_check_log_entries(uts, flags, min, max); \ + int ret = do_check_log_entries(uts, flags, min, max, "func"); \ if (ret) \ return ret; \ } while (0) @@ -192,6 +196,46 @@ int log_test_file_mid(struct unit_test_state *uts) } LOG_TEST_FLAGS(log_test_file_mid, UTF_CONSOLE);
+/* Check passing and failing function filters */ +int log_test_func(struct unit_test_state *uts) +{ + int filt; + + filt = log_add_filter_flags("console", NULL, LOGL_MAX, "file", "func", + 0); + ut_assert(filt >= 0); + + log_run_func("func"); + check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE); + + log_run_func("fnc2"); + do_check_log_entries(uts, EXPECT_FORCE, LOGL_FIRST, _LOG_MAX_LEVEL, + "fnc2"); + + ut_assertok(log_remove_filter("console", filt)); + + return 0; +} +LOG_TEST_FLAGS(log_test_func, UTF_CONSOLE); + +/* Check a passing function filter (middle of list) */ +int log_test_func_mid(struct unit_test_state *uts) +{ + int filt; + + filt = log_add_filter_flags("console", NULL, LOGL_MAX, "file", + "bad1,func,bad2", 0); + ut_assert(filt >= 0); + + log_run_func("func"); + check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE); + + ut_assertok(log_remove_filter("console", filt)); + + return 0; +} +LOG_TEST_FLAGS(log_test_func_mid, UTF_CONSOLE); + /* Check a log level filter */ int log_test_level(struct unit_test_state *uts) {
participants (1)
-
Heinrich Schuchardt