From cebd140bee354dda074167f11e498f52651e6d7e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Krzysztof=20Chru=C5=9Bci=C5=84ski?= Date: Wed, 30 Aug 2023 14:05:12 +0200 Subject: [PATCH] logging: log_output: Add optional tid formatting MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add option to prefix log message with thread ID or thread name. Align tests and add test case to the log_output test. Signed-off-by: Krzysztof Chruściński --- include/zephyr/logging/log_backend_std.h | 4 ++ include/zephyr/logging/log_output.h | 6 +++ subsys/logging/log_output.c | 22 +++++++-- .../logging/log_output/src/log_output_test.c | 45 +++++++++++++++---- tests/subsys/logging/log_output/testcase.yaml | 6 +++ .../log_timestamp/src/log_timestamp_test.c | 2 +- 6 files changed, 73 insertions(+), 12 deletions(-) diff --git a/include/zephyr/logging/log_backend_std.h b/include/zephyr/logging/log_backend_std.h index df26131c3e..b053ad9688 100644 --- a/include/zephyr/logging/log_backend_std.h +++ b/include/zephyr/logging/log_backend_std.h @@ -33,6 +33,10 @@ static inline uint32_t log_backend_std_get_flags(void) flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; } + if (IS_ENABLED(CONFIG_LOG_THREAD_ID_PREFIX)) { + flags |= LOG_OUTPUT_FLAG_THREAD; + } + return flags; } diff --git a/include/zephyr/logging/log_output.h b/include/zephyr/logging/log_output.h index 04816333e5..e55170605c 100644 --- a/include/zephyr/logging/log_output.h +++ b/include/zephyr/logging/log_output.h @@ -10,6 +10,7 @@ #include #include #include +#include #ifdef __cplusplus extern "C" { @@ -50,6 +51,9 @@ extern "C" { */ #define LOG_OUTPUT_FLAG_FORMAT_SYSLOG BIT(6) +/** @brief Flag thread id or name prefix. */ +#define LOG_OUTPUT_FLAG_THREAD BIT(7) + /**@} */ /** @brief Supported backend logging format types for use @@ -144,6 +148,7 @@ void log_output_msg_process(const struct log_output *log_output, * @param timestamp Timestamp. * @param domain Domain name string. Can be NULL. * @param source Source name string. Can be NULL. + * @param tid Thread ID. * @param level Criticality level. * @param package Cbprintf package with a logging message string. * @param data Data passed to hexdump API. Can bu NULL. @@ -154,6 +159,7 @@ void log_output_process(const struct log_output *log_output, log_timestamp_t timestamp, const char *domain, const char *source, + const k_tid_t tid, uint8_t level, const uint8_t *package, const uint8_t *data, diff --git a/subsys/logging/log_output.c b/subsys/logging/log_output.c index 3b77f6f556..ecfab72cac 100644 --- a/subsys/logging/log_output.c +++ b/subsys/logging/log_output.c @@ -325,8 +325,10 @@ static void color_postfix(const struct log_output *output, static int ids_print(const struct log_output *output, bool level_on, bool func_on, + bool thread_on, const char *domain, const char *source, + const k_tid_t tid, uint32_t level) { int total = 0; @@ -335,6 +337,15 @@ static int ids_print(const struct log_output *output, total += print_formatted(output, "<%s> ", severity[level]); } + if (IS_ENABLED(CONFIG_LOG_THREAD_ID_PREFIX) && thread_on) { + if (IS_ENABLED(CONFIG_THREAD_NAME)) { + total += print_formatted(output, "[%s] ", + tid == NULL ? "irq" : k_thread_name_get(tid)); + } else { + total += print_formatted(output, "[%p] ", tid); + } + } + if (domain) { total += print_formatted(output, "%s/", domain); } @@ -430,6 +441,7 @@ static uint32_t prefix_print(const struct log_output *output, log_timestamp_t timestamp, const char *domain, const char *source, + const k_tid_t tid, uint8_t level) { __ASSERT_NO_MSG(level <= LOG_LEVEL_DBG); @@ -438,6 +450,8 @@ static uint32_t prefix_print(const struct log_output *output, bool stamp = flags & LOG_OUTPUT_FLAG_TIMESTAMP; bool colors_on = flags & LOG_OUTPUT_FLAG_COLORS; bool level_on = flags & LOG_OUTPUT_FLAG_LEVEL; + bool thread_on = IS_ENABLED(CONFIG_LOG_THREAD_ID_PREFIX) && + (flags & LOG_OUTPUT_FLAG_THREAD); const char *tag = IS_ENABLED(CONFIG_LOG) ? z_log_get_tag() : NULL; if (IS_ENABLED(CONFIG_LOG_BACKEND_NET) && @@ -475,7 +489,7 @@ static uint32_t prefix_print(const struct log_output *output, color_prefix(output, colors_on, level); } - length += ids_print(output, level_on, func_on, domain, source, level); + length += ids_print(output, level_on, func_on, thread_on, domain, source, tid, level); return length; } @@ -492,6 +506,7 @@ void log_output_process(const struct log_output *output, log_timestamp_t timestamp, const char *domain, const char *source, + const k_tid_t tid, uint8_t level, const uint8_t *package, const uint8_t *data, @@ -503,7 +518,8 @@ void log_output_process(const struct log_output *output, cbprintf_cb cb; if (!raw_string) { - prefix_offset = prefix_print(output, flags, 0, timestamp, domain, source, level); + prefix_offset = prefix_print(output, flags, 0, timestamp, + domain, source, tid, level); cb = out_func; } else { prefix_offset = 0; @@ -560,7 +576,7 @@ void log_output_msg_process(const struct log_output *output, uint8_t *package = log_msg_get_package(msg, &plen); uint8_t *data = log_msg_get_data(msg, &dlen); - log_output_process(output, timestamp, NULL, sname, level, + log_output_process(output, timestamp, NULL, sname, (k_tid_t)log_msg_get_tid(msg), level, plen > 0 ? package : NULL, data, dlen, flags); } diff --git a/tests/subsys/logging/log_output/src/log_output_test.c b/tests/subsys/logging/log_output/src/log_output_test.c index 4d241f5cb2..1166bf815e 100644 --- a/tests/subsys/logging/log_output/src/log_output_test.c +++ b/tests/subsys/logging/log_output/src/log_output_test.c @@ -54,7 +54,7 @@ ZTEST(test_log_output, test_no_flags) err = cbprintf_package(package, sizeof(package), 0, TEST_STR); zassert_true(err > 0); - log_output_process(&log_output, 0, NULL, SNAME, LOG_LEVEL_INF, package, NULL, 0, 0); + log_output_process(&log_output, 0, NULL, SNAME, NULL, LOG_LEVEL_INF, package, NULL, 0, 0); mock_buffer[mock_len] = '\0'; zassert_equal(strcmp(exp_str, mock_buffer), 0); @@ -69,7 +69,7 @@ ZTEST(test_log_output, test_raw) err = cbprintf_package(package, sizeof(package), 0, TEST_STR); zassert_true(err > 0); - log_output_process(&log_output, 0, NULL, SNAME, LOG_LEVEL_INTERNAL_RAW_STRING, + log_output_process(&log_output, 0, NULL, SNAME, NULL, LOG_LEVEL_INTERNAL_RAW_STRING, package, NULL, 0, 0); mock_buffer[mock_len] = '\0'; @@ -85,7 +85,7 @@ ZTEST(test_log_output, test_no_flags_dname) err = cbprintf_package(package, sizeof(package), 0, TEST_STR); zassert_true(err > 0); - log_output_process(&log_output, 0, DNAME, SNAME, LOG_LEVEL_INF, package, NULL, 0, 0); + log_output_process(&log_output, 0, DNAME, SNAME, NULL, LOG_LEVEL_INF, package, NULL, 0, 0); mock_buffer[mock_len] = '\0'; zassert_equal(strcmp(exp_str, mock_buffer), 0); @@ -101,7 +101,7 @@ ZTEST(test_log_output, test_level_flag) err = cbprintf_package(package, sizeof(package), 0, TEST_STR); zassert_true(err > 0); - log_output_process(&log_output, 0, DNAME, SNAME, LOG_LEVEL_INF, + log_output_process(&log_output, 0, DNAME, SNAME, NULL, LOG_LEVEL_INF, package, NULL, 0, flags); mock_buffer[mock_len] = '\0'; @@ -120,7 +120,7 @@ ZTEST(test_log_output, test_ts_flag) err = cbprintf_package(package, sizeof(package), 0, TEST_STR); zassert_true(err > 0); - log_output_process(&log_output, 0, DNAME, SNAME, LOG_LEVEL_INF, + log_output_process(&log_output, 0, DNAME, SNAME, NULL, LOG_LEVEL_INF, package, NULL, 0, flags); mock_buffer[mock_len] = '\0'; @@ -140,7 +140,7 @@ ZTEST(test_log_output, test_format_ts) err = cbprintf_package(package, sizeof(package), 0, TEST_STR); zassert_true(err > 0); - log_output_process(&log_output, 1000000, DNAME, SNAME, LOG_LEVEL_INF, + log_output_process(&log_output, 1000000, DNAME, SNAME, NULL, LOG_LEVEL_INF, package, NULL, 0, flags); mock_buffer[mock_len] = '\0'; @@ -178,7 +178,7 @@ ZTEST(test_log_output, test_levels) for (int i = 0; i < ARRAY_SIZE(exp_strs); i++) { reset_mock_buffer(); - log_output_process(&log_output, 0, NULL, SNAME, levels[i], + log_output_process(&log_output, 0, NULL, SNAME, NULL, levels[i], package, NULL, 0, flags); mock_buffer[mock_len] = '\0'; @@ -210,7 +210,7 @@ ZTEST(test_log_output, test_colors) for (int i = 0; i < ARRAY_SIZE(exp_strs); i++) { reset_mock_buffer(); - log_output_process(&log_output, 0, NULL, SNAME, levels[i], + log_output_process(&log_output, 0, NULL, SNAME, NULL, levels[i], package, NULL, 0, flags); mock_buffer[mock_len] = '\0'; @@ -218,6 +218,35 @@ ZTEST(test_log_output, test_colors) } } +ZTEST(test_log_output, test_thread_id) +{ + if (!IS_ENABLED(CONFIG_LOG_THREAD_ID_PREFIX)) { + return; + } + + char exp_str[256]; + char package[256]; + + if (IS_ENABLED(CONFIG_THREAD_NAME)) { + sprintf(exp_str, " [%s] src: Test\r\n", k_thread_name_get(k_current_get())); + } else { + sprintf(exp_str, " [%p] src: Test\r\n", k_current_get()); + } + + uint32_t flags = LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_THREAD; + int err; + + err = cbprintf_package(package, sizeof(package), 0, "Test"); + zassert_true(err > 0); + + log_output_process(&log_output, 0, NULL, SNAME, k_current_get(), 1, + package, NULL, 0, flags); + + mock_buffer[mock_len] = '\0'; + printk("%s", mock_buffer); + zassert_equal(strcmp(exp_str, mock_buffer), 0); +} + static void before(void *notused) { reset_mock_buffer(); diff --git a/tests/subsys/logging/log_output/testcase.yaml b/tests/subsys/logging/log_output/testcase.yaml index 3a5c7b1cc4..66b8f67508 100644 --- a/tests/subsys/logging/log_output/testcase.yaml +++ b/tests/subsys/logging/log_output/testcase.yaml @@ -15,3 +15,9 @@ tests: - logging extra_configs: - CONFIG_LOG_TIMESTAMP_64BIT=y + logging.log_output.thread_id: + tags: + - log_output + - logging + extra_configs: + - CONFIG_LOG_THREAD_ID_PREFIX=y diff --git a/tests/subsys/logging/log_timestamp/src/log_timestamp_test.c b/tests/subsys/logging/log_timestamp/src/log_timestamp_test.c index 716f3cfd2d..f6b65042d0 100644 --- a/tests/subsys/logging/log_timestamp/src/log_timestamp_test.c +++ b/tests/subsys/logging/log_timestamp/src/log_timestamp_test.c @@ -71,7 +71,7 @@ ZTEST(test_timestamp, test_custom_timestamp) err = cbprintf_package(package, sizeof(package), 0, TEST_STR); zassert_true(err > 0); - log_output_process(&log_output, 1, DNAME, SNAME, LOG_LEVEL_INF, + log_output_process(&log_output, 1, DNAME, SNAME, NULL, LOG_LEVEL_INF, package, NULL, 0, flags); mock_buffer[mock_len] = '\0';