Each uclass has a driver name which we can use to look up the uclass. This is useful for logging, where the uclass ID is used as the category.

Add a function to handle this, as well as a test.

Signed-off-by: Simon Glass sjg@chromium.org ---

drivers/core/uclass.c | 14 ++++++++++++++ include/dm/uclass.h | 8 ++++++++ test/dm/core.c | 9 +++++++++ 3 files changed, 31 insertions(+)

diff --git a/drivers/core/uclass.c b/drivers/core/uclass.c index f5e4067922..1aedaa08f0 100644 --- a/drivers/core/uclass.c +++ b/drivers/core/uclass.c @@ -158,6 +158,20 @@ const char *uclass_get_name(enum uclass_id id) return uc->uc_drv->name; }

+enum uclass_id uclass_get_by_name(const char *name) +{ + int i; + + for (i = 0; i < UCLASS_COUNT; i++) { + struct uclass_driver *uc_drv = lists_uclass_lookup(i); + + if (uc_drv && !strcmp(uc_drv->name, name)) + return i; + } + + return UCLASS_INVALID; +} + int uclass_find_device(enum uclass_id id, int index, struct udevice **devp) { struct uclass *uc; diff --git a/include/dm/uclass.h b/include/dm/uclass.h index 18188497c2..88f6ef4ed5 100644 --- a/include/dm/uclass.h +++ b/include/dm/uclass.h @@ -127,6 +127,14 @@ int uclass_get(enum uclass_id key, struct uclass **ucp); */ const char *uclass_get_name(enum uclass_id id);

+/** + * uclass_get_by_name() - Look up a uclass by its driver name + * + * @name: Name to look up + * @returns the associated uclass ID, or UCLASS_INVALID if not found + */ +enum uclass_id uclass_get_by_name(const char *name); + /** * uclass_get_device() - Get a uclass device based on an ID and index * diff --git a/test/dm/core.c b/test/dm/core.c index 50ee41b9e2..052bf8fffb 100644 --- a/test/dm/core.c +++ b/test/dm/core.c @@ -862,3 +862,12 @@ static int dm_test_device_get_uclass_id(struct unit_test_state *uts) return 0; } DM_TEST(dm_test_device_get_uclass_id, DM_TESTF_SCAN_PDATA); + +static int dm_test_uclass_names(struct unit_test_state *uts) +{ + ut_asserteq_str("test", uclass_get_name(UCLASS_TEST)); + ut_asserteq(UCLASS_TEST, uclass_get_by_name("test")); + + return 0; +} +DM_TEST(dm_test_uclass_names, DM_TESTF_SCAN_PDATA);

Category and level both use an enum for their ID values. Add functions to convert these IDs to strings and vice versa. This will allow the log to output the strings instead of the (inscrutable) values.

At the same time, add a new 'driver-model' category, to cover core driver-model functions and fix an incorrect value for LOGL_MAX.

Tests will be added with the new 'log' subcommands.

Signed-off-by: Simon Glass sjg@chromium.org ---

common/log.c | 67 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ include/log.h | 39 ++++++++++++++++++++++++++++++++-- 2 files changed, 104 insertions(+), 2 deletions(-)

diff --git a/common/log.c b/common/log.c index 45e46dd520..5761a2ce76 100644 --- a/common/log.c +++ b/common/log.c @@ -10,9 +10,76 @@ #include <common.h> #include <log.h> #include <malloc.h> +#include <dm/uclass.h>

DECLARE_GLOBAL_DATA_PTR;

+static const char *log_cat_name[LOGC_COUNT - LOGC_NONE] = { + "none", + "arch", + "board", + "core", + "driver-model", + "device-tree", +}; + +static const char *log_level_name[LOGL_COUNT] = { + "EMERG", + "ALERT", + "CRIT", + "ERR", + "WARNING", + "NOTICE", + "INFO", + "DEBUG", + "CONTENT", + "IO", +}; + +const char *log_get_cat_name(enum log_category_t cat) +{ + if (cat > LOGC_COUNT) + return "invalid"; + if (log_uc_cat(cat) >= LOGC_NONE) + return log_cat_name[cat - LOGC_NONE]; + + return uclass_get_name(log_uc_cat(cat)); +} + +enum log_category_t log_get_cat_by_name(const char *name) +{ + enum uclass_id id; + int i; + + for (i = LOGC_NONE; i < LOGC_COUNT; i++) + if (!strcmp(name, log_cat_name[i - LOGC_NONE])) + return i; + id = uclass_get_by_name(name); + if (id != UCLASS_INVALID) + return (enum log_category_t)id; + + return LOGC_NONE; +} + +const char *log_get_level_name(enum log_level_t level) +{ + if (level >= LOGL_COUNT) + return "INVALID"; + return log_level_name[level]; +} + +enum log_level_t log_get_level_by_name(const char *name) +{ + int i; + + for (i = 0; i < LOGL_COUNT; i++) { + if (!strcasecmp(log_level_name[i], name)) + return i; + } + + return LOGL_NONE; +} + static struct log_device *log_device_find_by_name(const char *drv_name) { struct log_device *ldev; diff --git a/include/log.h b/include/log.h index 8083b64831..5133213acf 100644 --- a/include/log.h +++ b/include/log.h @@ -27,8 +27,10 @@ enum log_level_t { LOGL_DEBUG_IO, /* Debug message showing hardware I/O access */

LOGL_COUNT, + LOGL_NONE, + LOGL_FIRST = LOGL_EMERG, - LOGL_MAX = LOGL_DEBUG, + LOGL_MAX = LOGL_DEBUG_IO, };

/** @@ -42,7 +44,8 @@ enum log_category_t { LOGC_ARCH, LOGC_BOARD, LOGC_CORE, - LOGC_DT, + LOGC_DM, /* Core driver-model */ + LOGC_DT, /* Device-tree */

LOGC_COUNT, LOGC_END, @@ -256,6 +259,38 @@ struct log_filter { #define LOG_DRIVER(_name) \ ll_entry_declare(struct log_driver, _name, log_driver)

+/** + * log_get_cat_name() - Get the name of a category + * + * @cat: Category to look up + * @return category name (which may be a uclass driver name) + */ +const char *log_get_cat_name(enum log_category_t cat); + +/** + * log_get_cat_by_name() - Look up a category by name + * + * @name: Name to look up + * @return category ID, or LOGC_NONE if not found + */ +enum log_category_t log_get_cat_by_name(const char *name); + +/** + * log_get_level_name() - Get the name of a log level + * + * @level: Log level to look up + * @return log level name (in ALL CAPS) + */ +const char *log_get_level_name(enum log_level_t level); + +/** + * log_get_level_by_name() - Look up a log level by name + * + * @name: Name to look up + * @return log level ID, or LOGL_NONE if not found + */ +enum log_level_t log_get_level_by_name(const char *name); + /* Handle the 'log test' command */ int do_log_test(cmd_tbl_t *cmdtp, int flag, int argc, char *const argv[]);

It is useful to be able to control the output format of log records on the console. As a starting point, add definitions for controlling which elements of the log record are displayed. Use function and message as the default, since these are the most useful fields.

Signed-off-by: Simon Glass sjg@chromium.org ---

common/log.c | 1 + include/asm-generic/global_data.h | 1 + include/log.h | 14 ++++++++++++++ 3 files changed, 16 insertions(+)

diff --git a/common/log.c b/common/log.c index 5761a2ce76..7559d74e90 100644 --- a/common/log.c +++ b/common/log.c @@ -307,6 +307,7 @@ int log_init(void) } gd->flags |= GD_FLG_LOG_READY; gd->default_log_level = LOGL_INFO; + gd->log_fmt = LOGF_DEFAULT;

return 0; } diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h index 73e036d6fd..f1c21dfd20 100644 --- a/include/asm-generic/global_data.h +++ b/include/asm-generic/global_data.h @@ -118,6 +118,7 @@ typedef struct global_data { int log_drop_count; /* Number of dropped log messages */ int default_log_level; /* For devices with no filters */ struct list_head log_head; /* List of struct log_device */ + int log_fmt; /* Mask containing log format info */ #endif } gd_t; #endif diff --git a/include/log.h b/include/log.h index 5133213acf..828919a409 100644 --- a/include/log.h +++ b/include/log.h @@ -291,6 +291,20 @@ const char *log_get_level_name(enum log_level_t level); */ enum log_level_t log_get_level_by_name(const char *name);

+/* Log format flags (bit numbers) for gd->log_fmt. See log_fmt_chars */ +enum log_fmt { + LOGF_CAT = 0, + LOGF_LEVEL, + LOGF_FILE, + LOGF_LINE, + LOGF_FUNC, + LOGF_MSG, + + LOGF_COUNT, + LOGF_DEFAULT = (1 << LOGF_FUNC) | (1 << LOGF_MSG), + LOGF_ALL = 0x3f, +}; + /* Handle the 'log test' command */ int do_log_test(cmd_tbl_t *cmdtp, int flag, int argc, char *const argv[]);

At present this just outputs the message. Update it to output whatever the format requests.

Signed-off-by: Simon Glass sjg@chromium.org ---

common/log_console.c | 27 ++++++++++++++++++++++++++- test/py/tests/test_log.py | 4 ++-- 2 files changed, 28 insertions(+), 3 deletions(-)

diff --git a/common/log_console.c b/common/log_console.c index 5af73bd8be..2902733078 100644 --- a/common/log_console.c +++ b/common/log_console.c @@ -10,9 +10,34 @@ #include <common.h> #include <log.h>

+DECLARE_GLOBAL_DATA_PTR; + static int log_console_emit(struct log_device *ldev, struct log_rec *rec) { - puts(rec->msg); + int fmt = gd->log_fmt; + + /* + * The output format is designed to give someone a fighting chance of + * figuring out which field is which: + * - level is in CAPS + * - cat is lower case and ends with comma + * - file normally has a .c extension and ends with a colon + * - line is integer and ends with a - + * - function is an identifier and ends with () + * - message has a space before it unless it is on its own + */ + if (fmt & (1 << LOGF_LEVEL)) + printf("%s.", log_get_level_name(rec->level)); + if (fmt & (1 << LOGF_CAT)) + printf("%s,", log_get_cat_name(rec->cat)); + if (fmt & (1 << LOGF_FILE)) + printf("%s:", rec->file); + if (fmt & (1 << LOGF_LINE)) + printf("%d-", rec->line); + if (fmt & (1 << LOGF_FUNC)) + printf("%s()", rec->func); + if (fmt & (1 << LOGF_MSG)) + printf("%s%s", fmt != (1 << LOGF_MSG) ? " " : "", rec->msg);

return 0; } diff --git a/test/py/tests/test_log.py b/test/py/tests/test_log.py index fa9a25e8dc..517f415143 100644 --- a/test/py/tests/test_log.py +++ b/test/py/tests/test_log.py @@ -28,9 +28,9 @@ def test_log(u_boot_console): """ for i in range(max_level): if mask & 1: - assert 'log %d' % i == lines.next() + assert 'log_run() log %d' % i == lines.next() if mask & 3: - assert '_log %d' % i == lines.next() + assert 'func() _log %d' % i == lines.next()

def run_test(testnum): """Run a particular test number (the 'log test' command)

Add a 'log format' command which can display or change the log output format. This is useful for changing how much information is displayed. The ordering of the fields is fixed.

Signed-off-by: Simon Glass sjg@chromium.org ---

cmd/log.c | 43 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 43 insertions(+)

diff --git a/cmd/log.c b/cmd/log.c index abc523b497..e038bc3269 100644 --- a/cmd/log.c +++ b/cmd/log.c @@ -10,6 +10,8 @@ #include <dm.h> #include <log.h>

+static char log_fmt_chars[LOGF_COUNT] = "clFLfm"; + static int do_log_level(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) { @@ -21,11 +23,48 @@ static int do_log_level(cmd_tbl_t *cmdtp, int flag, int argc, return 0; }

+static int do_log_format(cmd_tbl_t *cmdtp, int flag, int argc, + char * const argv[]) +{ + int i; + + if (argc > 1) { + const char *str = argv[1]; + + if (!strcmp(str, "default")) { + gd->log_fmt = LOGF_DEFAULT; + } else if (!strcmp(str, "all")) { + gd->log_fmt = LOGF_ALL; + } else { + gd->log_fmt = 0; + for (; *str; str++) { + char *ptr = strchr(log_fmt_chars, *str); + + if (!ptr) { + printf("Invalid log char '%c'\n", *str); + return CMD_RET_FAILURE; + } + gd->log_fmt |= 1 << (ptr - log_fmt_chars); + } + } + } else { + printf("Log format: "); + for (i = 0; i < LOGF_COUNT; i++) { + if (gd->log_fmt & (1 << i)) + printf("%c", log_fmt_chars[i]); + } + printf("\n"); + } + + return 0; +} + static cmd_tbl_t log_sub[] = { U_BOOT_CMD_MKENT(level, CONFIG_SYS_MAXARGS, 1, do_log_level, "", ""), #ifdef CONFIG_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, "", ""), };

static int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) @@ -52,6 +91,10 @@ static char log_help_text[] = #ifdef CONFIG_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" + "\tor 'default', equivalent to 'fm', or 'all' for all" ; #endif

Add a 'log rec' command which allows a log record to be manually output. This is useful for scripts which want full control over what is logged. It also permits easy testing of the log system.

Signed-off-by: Simon Glass sjg@chromium.org ---

cmd/log.c | 41 ++++++++++++++++++++++++++++++++++++++++- 1 file changed, 40 insertions(+), 1 deletion(-)

diff --git a/cmd/log.c b/cmd/log.c index e038bc3269..12bac0e03c 100644 --- a/cmd/log.c +++ b/cmd/log.c @@ -59,12 +59,49 @@ static int do_log_format(cmd_tbl_t *cmdtp, int flag, int argc, return 0; }

+static int do_log_rec(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) +{ + enum log_category_t cat; + enum log_level_t level; + const char *file; + uint line; + const char *func; + const char *msg; + char *end; + + if (argc < 7) + return CMD_RET_USAGE; + cat = log_get_cat_by_name(argv[1]); + level = simple_strtoul(argv[2], &end, 10); + if (end == argv[2]) { + level = log_get_level_by_name(argv[2]); + + if (level == LOGL_NONE) { + printf("Invalid log level '%s'\n", argv[2]); + return CMD_RET_USAGE; + } + } + if (level >= LOGL_MAX) { + printf("Invalid log level %u\n", level); + return CMD_RET_USAGE; + } + file = argv[3]; + line = simple_strtoul(argv[4], NULL, 10); + func = argv[5]; + msg = argv[6]; + if (_log(cat, level, file, line, func, "%s\n", msg)) + return CMD_RET_FAILURE; + + return 0; +} + static cmd_tbl_t log_sub[] = { U_BOOT_CMD_MKENT(level, CONFIG_SYS_MAXARGS, 1, do_log_level, "", ""), #ifdef CONFIG_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, "", ""), };

static int do_log(cmd_tbl_t *cmdtp, int flag, int argc, char * const argv[]) @@ -94,7 +131,9 @@ static char log_help_text[] = "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" - "\tor 'default', equivalent to 'fm', or 'all' for all" + "\tor 'default', equivalent to 'fm', or 'all' for all\n" + "log rec <category> <level> <file> <line> <func> <message> - " + "output a log record" ; #endif

Add a test of the 'log format' and 'log rec' commands. This also covers things like log_get_cat_by_name(), since they are used by these commands. Fix a style nit in the tests also.

Signed-off-by: Simon Glass sjg@chromium.org ---

test/py/tests/test_log.py | 28 +++++++++++++++++++++++++++- 1 file changed, 27 insertions(+), 1 deletion(-)

diff --git a/test/py/tests/test_log.py b/test/py/tests/test_log.py index 517f415143..76f9236412 100644 --- a/test/py/tests/test_log.py +++ b/test/py/tests/test_log.py @@ -40,7 +40,6 @@ def test_log(u_boot_console): Returns: iterator containing the lines output from the command """ - with cons.log.section('basic'): output = u_boot_console.run_command('log test %d' % testnum) split = output.replace('\r', '').splitlines() @@ -99,3 +98,30 @@ def test_log(u_boot_console): test7() test8() test9() + +@pytest.mark.buildconfigspec('log') +def test_log_format(u_boot_console): + """Test the 'log format' and 'log rec' commands""" + def run_with_format(fmt, expected_output): + """Set up the log format and then write a log record + + Args: + fmt: Format to use for 'log format' + expected_output: Expected output from the 'log rec' command + """ + output = cons.run_command('log format %s' % fmt) + assert output == '' + output = cons.run_command('log rec arch notice file.c 123 func msg') + assert output == expected_output + + cons = u_boot_console + with cons.log.section('format'): + run_with_format('all', 'NOTICE.arch,file.c:123-func() msg') + output = cons.run_command('log format') + assert output == 'Log format: clFLfm' + + run_with_format('fm', 'func() msg') + run_with_format('clfm', 'NOTICE.arch,func() msg') + run_with_format('FLfm', 'file.c:123-func() msg') + run_with_format('lm', 'NOTICE. msg') + run_with_format('m', 'msg')

Add some notes about recent new features.

Signed-off-by: Simon Glass sjg@chromium.org ---

doc/README.log | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+)

diff --git a/doc/README.log b/doc/README.log index f653fe7d79..54d9a8e1b9 100644 --- a/doc/README.log +++ b/doc/README.log @@ -68,6 +68,19 @@ If CONFIG_LOG is not set, then no logging will be available. The above have SPL versions also, e.g. CONFIG_SPL_MAX_LOG_LEVEL.

+Log commands +------------ + +The 'log' command provides access to several features: + + level - access the default log level + format - access the console log format + rec - output a log record + test - run tests + +Type 'help log' for details. + + Using DEBUG -----------

@@ -94,6 +107,20 @@ enabled or disabled independently: console - goes to stdout

+Log format +---------- + +You can control the log format using the 'log format' command. The basic +format is: + + LEVEL.category,file.c:123-func() message + +In the above, file.c:123 is the filename where the log record was generated and +func() is the function name. By default ('log format default') only the +function name and message are displayed on the console. You can control which +fields are present, but not the field order. + + Filters -------

When functions return an error it propagates up the stack to the point where it is reported. Often the error code provides enough information about the root cause of the error that this is obvious what went wrong.

However in some cases the error may be hard to trace. For example if a driver uses several devices to perform an operation, it may not be obvious which one failed.

Add a log_ret() macro to help with this. This can be used to wrap any error-return value. The logging system will then output a log record when the original error is generated, making it easy to trace the call stack of the error.

This macro can significantly impact code size, so its use is controlled by a Kconfig option, which is enabled for sandbox.

Signed-off-by: Simon Glass sjg@chromium.org ---

common/Kconfig | 13 +++++++++++++ configs/sandbox_defconfig | 1 + doc/README.log | 8 ++++++++ include/log.h | 11 +++++++++++ 4 files changed, 33 insertions(+)

diff --git a/common/Kconfig b/common/Kconfig index 4da095a4fd..c9833b3226 100644 --- a/common/Kconfig +++ b/common/Kconfig @@ -504,6 +504,19 @@ config LOG_TEST in various different ways to test that the logging system works correctly with varoius settings.

+config LOG_ERROR_RETURN + bool "Log all functions which return an error" + depends on LOG + help + When an error is returned in U-Boot it is sometimes difficult to + figure out the root cause. For eaxmple, reading from SPI flash may + fail due to a problem in the SPI controller or due to the flash part + not returning the expected information. This option changes + log_ret() to log any errors it sees. With this option disabled, + log_ret() is a nop. + + You can add log_ret() to all functions which return an error code. + endmenu

config DEFAULT_FDT_FILE diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig index 7efb4ebf11..41a2e34235 100644 --- a/configs/sandbox_defconfig +++ b/configs/sandbox_defconfig @@ -18,6 +18,7 @@ CONFIG_PRE_CONSOLE_BUFFER=y CONFIG_PRE_CON_BUF_ADDR=0x100000 CONFIG_LOG=y CONFIG_LOG_MAX_LEVEL=6 +CONFIG_LOG_ERROR_RETURN=y CONFIG_CMD_CPU=y CONFIG_CMD_LICENSE=y CONFIG_CMD_BOOTZ=y diff --git a/doc/README.log b/doc/README.log index 54d9a8e1b9..2abaee0c10 100644 --- a/doc/README.log +++ b/doc/README.log @@ -148,6 +148,14 @@ Also debug() and error() will generate log records - these use LOG_CATEGORY as the category, so you should #define this right at the top of the source file to ensure the category is correct.

+You can also define CONFIG_LOG_ERROR_RETURN to enable the log_ret() macro. This +can be used whenever your function returns an error value: + + return log_ret(uclass_first_device(UCLASS_MMC, &dev)); + +This will write a log record when an error code is detected (a value < 0). This +can make it easier to trace errors that are generated deep in the call stack. +

Code size --------- diff --git a/include/log.h b/include/log.h index 828919a409..68368d5cf1 100644 --- a/include/log.h +++ b/include/log.h @@ -159,6 +159,17 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line, ({ if (!(x) && _DEBUG) \ __assert_fail(#x, __FILE__, __LINE__, __func__); })

+#ifdef CONFIG_LOG_ERROR_RETURN +#define log_ret(_ret) ({ \ + int __ret = (_ret); \ + if (__ret < 0) \ + log(LOG_CATEGORY, LOGL_ERR, "returning err=%d\n", __ret); \ + __ret; \ + }) +#else +#define log_ret(_ret) (_ret) +#endif + /** * struct log_rec - a single log record *