diff --git a/components/bootloader/Kconfig.log b/components/bootloader/Kconfig.log new file mode 100644 index 0000000000..151890753a --- /dev/null +++ b/components/bootloader/Kconfig.log @@ -0,0 +1,34 @@ +menu "Log" + + choice BOOTLOADER_LOG_LEVEL + bool "Bootloader log verbosity" + default BOOTLOADER_LOG_LEVEL_INFO + help + Specify how much output to see in bootloader logs. + + config BOOTLOADER_LOG_LEVEL_NONE + bool "No output" + config BOOTLOADER_LOG_LEVEL_ERROR + bool "Error" + config BOOTLOADER_LOG_LEVEL_WARN + bool "Warning" + config BOOTLOADER_LOG_LEVEL_INFO + bool "Info" + config BOOTLOADER_LOG_LEVEL_DEBUG + bool "Debug" + config BOOTLOADER_LOG_LEVEL_VERBOSE + bool "Verbose" + endchoice + + config BOOTLOADER_LOG_LEVEL + int + default 0 if BOOTLOADER_LOG_LEVEL_NONE + default 1 if BOOTLOADER_LOG_LEVEL_ERROR + default 2 if BOOTLOADER_LOG_LEVEL_WARN + default 3 if BOOTLOADER_LOG_LEVEL_INFO + default 4 if BOOTLOADER_LOG_LEVEL_DEBUG + default 5 if BOOTLOADER_LOG_LEVEL_VERBOSE + + orsource "Kconfig.log.format" + +endmenu diff --git a/components/bootloader/Kconfig.log.format b/components/bootloader/Kconfig.log.format new file mode 100644 index 0000000000..985fa5f43a --- /dev/null +++ b/components/bootloader/Kconfig.log.format @@ -0,0 +1,36 @@ +menu "Format" + + config BOOTLOADER_LOG_COLORS + bool "Color" + default y + help + Use ANSI terminal colors in log output + Enable ANSI terminal color codes. + In order to view these, your terminal program must support ANSI color codes. + + choice BOOTLOADER_LOG_TIMESTAMP_SOURCE + prompt "Timestamp" + default BOOTLOADER_LOG_TIMESTAMP_SOURCE_CPU_TICKS + help + Choose what sort of timestamp is displayed in the log output: + + - "None" - The log will only contain the actual log messages themselves + without any time-related information. Avoiding timestamps can help conserve + processing power and memory. It might useful when you + perform log analysis or debugging, sometimes it's more straightforward + to work with logs that lack timestamps, especially if the time of occurrence + is not critical for understanding the issues. + "I log_test: info message" + + - "Milliseconds since boot" is calculated from the RTOS tick count multiplied + by the tick period. This time will reset after a software reboot. + "I (112500) log_test: info message" + + config BOOTLOADER_LOG_TIMESTAMP_SOURCE_NONE + bool "None" + depends on No # hide it now, turn it on final MR + config BOOTLOADER_LOG_TIMESTAMP_SOURCE_CPU_TICKS + bool "Milliseconds Since Boot" + endchoice # BOOTLOADER_LOG_TIMESTAMP_SOURCE + +endmenu diff --git a/components/bootloader/Kconfig.projbuild b/components/bootloader/Kconfig.projbuild index d1ea31925e..ba6f69f01b 100644 --- a/components/bootloader/Kconfig.projbuild +++ b/components/bootloader/Kconfig.projbuild @@ -38,34 +38,7 @@ menu "Bootloader config" endchoice - choice BOOTLOADER_LOG_LEVEL - bool "Bootloader log verbosity" - default BOOTLOADER_LOG_LEVEL_INFO - help - Specify how much output to see in bootloader logs. - - config BOOTLOADER_LOG_LEVEL_NONE - bool "No output" - config BOOTLOADER_LOG_LEVEL_ERROR - bool "Error" - config BOOTLOADER_LOG_LEVEL_WARN - bool "Warning" - config BOOTLOADER_LOG_LEVEL_INFO - bool "Info" - config BOOTLOADER_LOG_LEVEL_DEBUG - bool "Debug" - config BOOTLOADER_LOG_LEVEL_VERBOSE - bool "Verbose" - endchoice - - config BOOTLOADER_LOG_LEVEL - int - default 0 if BOOTLOADER_LOG_LEVEL_NONE - default 1 if BOOTLOADER_LOG_LEVEL_ERROR - default 2 if BOOTLOADER_LOG_LEVEL_WARN - default 3 if BOOTLOADER_LOG_LEVEL_INFO - default 4 if BOOTLOADER_LOG_LEVEL_DEBUG - default 5 if BOOTLOADER_LOG_LEVEL_VERBOSE + orsource "Kconfig.log" menu "Serial Flash Configurations" config BOOTLOADER_SPI_CUSTOM_WP_PIN diff --git a/components/log/CMakeLists.txt b/components/log/CMakeLists.txt index c65fc621d7..e162bfb853 100644 --- a/components/log/CMakeLists.txt +++ b/components/log/CMakeLists.txt @@ -1,19 +1,24 @@ idf_build_get_property(target IDF_TARGET) -set(srcs "") +if(BOOTLOADER_BUILD) + set(system_target "noos") +else() + if(${target} STREQUAL "linux") + set(system_target "linux") + else() + set(system_target "os") + endif() +endif() + +set(srcs "src/${system_target}/log_timestamp.c" + "src/log_timestamp_common.c" + "src/${system_target}/log_lock.c") set(priv_requires "") -if(BOOTLOADER_BUILD) - list(APPEND srcs "log_noos.c") -else() - list(APPEND srcs "src/os/log_write.c") +if(NOT BOOTLOADER_BUILD) + list(APPEND priv_requires soc hal esp_hw_support) - if(${target} STREQUAL "linux") - list(APPEND srcs "log_linux.c") - else() - list(APPEND srcs "log_freertos.c") - list(APPEND priv_requires soc hal esp_hw_support) - endif() + list(APPEND srcs "src/os/log_write.c") # Buffer APIs call ESP_LOG_LEVEL -> esp_log_write, which can not used in bootloader. list(APPEND srcs "src/buffer/log_buffers.c" diff --git a/components/log/Kconfig.format b/components/log/Kconfig.format index 1ae55ba078..9e5b1bc6f7 100644 --- a/components/log/Kconfig.format +++ b/components/log/Kconfig.format @@ -13,24 +13,40 @@ menu "Format" help Choose what sort of timestamp is displayed in the log output: + - "None" - The log will only contain the actual log messages themselves + without any time-related information. Avoiding timestamps can help conserve + processing power and memory. It might useful when you + perform log analysis or debugging, sometimes it's more straightforward + to work with logs that lack timestamps, especially if the time of occurrence + is not critical for understanding the issues. + - "Milliseconds since boot" is calculated from the RTOS tick count multiplied by the tick period. This time will reset after a software reboot. e.g. (90000) - - "System time" is taken from POSIX time functions which use the chip's + - "System time (HH:MM:SS.sss)" is taken from POSIX time functions which use the chip's RTC and high resolution timers to maintain an accurate time. The system time is initialized to 0 on startup, it can be set with an SNTP sync, or with POSIX time functions. This time will not reset after a software reboot. e.g. (00:01:30.000) + - "System time (YY-MM-DD HH:MM:SS.sss)" it is the same as the above, + but also prints the date as well. + - NOTE: Currently this will not get used in logging from binary blobs (i.e WiFi & Bluetooth libraries), these will always print milliseconds since boot. + config LOG_TIMESTAMP_SOURCE_NONE + bool "None" + depends on No # hide it now, turn it on final MR config LOG_TIMESTAMP_SOURCE_RTOS bool "Milliseconds Since Boot" config LOG_TIMESTAMP_SOURCE_SYSTEM - bool "System Time" + bool "System Time (HH:MM:SS.sss)" + config LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + bool "System Time (YY-MM-DD HH:MM:SS.sss)" + depends on No # hide it now, turn it on final MR endchoice # LOG_TIMESTAMP_SOURCE endmenu diff --git a/components/log/host_test/log_test/main/log_test.cpp b/components/log/host_test/log_test/main/log_test.cpp index 0bd04363d7..040fbb97d3 100644 --- a/components/log/host_test/log_test/main/log_test.cpp +++ b/components/log/host_test/log_test/main/log_test.cpp @@ -11,11 +11,25 @@ #include #include "esp_log.h" #include "esp_private/log_util.h" +#include "esp_private/log_timestamp.h" +#include "sdkconfig.h" #include using namespace std; +#define EARLY_TIMESTAMP "[0-9]*" + +#if CONFIG_LOG_TIMESTAMP_SOURCE_RTOS +#define TIMESTAMP "[0-9]*" +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM +#define TIMESTAMP "[0-9]{2}:[0-9]{2}:[0-9]{2}\\.[0-9]{3}" +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL +#define TIMESTAMP "[0-9]{2}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\\.[0-9]{3}" +#else +#define TIMESTAMP "" +#endif + static const char *TEST_TAG = "test"; class BasicLogFixture { @@ -135,7 +149,7 @@ PutcFixture *PutcFixture::instance = nullptr; TEST_CASE("verbose log level") { PrintFixture fix(ESP_LOG_VERBOSE); - const std::regex test_print("V \\([0-9]*\\) test: verbose", std::regex::ECMAScript); + const std::regex test_print("V \\(" TIMESTAMP "\\) test: verbose", std::regex::ECMAScript); ESP_LOGV(TEST_TAG, "verbose"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -144,7 +158,7 @@ TEST_CASE("verbose log level") TEST_CASE("debug log level") { PrintFixture fix(ESP_LOG_DEBUG); - const std::regex test_print("D \\([0-9]*\\) test: debug", std::regex::ECMAScript); + const std::regex test_print("D \\(" TIMESTAMP "\\) test: debug", std::regex::ECMAScript); ESP_LOGD(TEST_TAG, "debug"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -153,7 +167,7 @@ TEST_CASE("debug log level") TEST_CASE("info log level") { PrintFixture fix(ESP_LOG_INFO); - const std::regex test_print("I \\([0-9]*\\) test: info", std::regex::ECMAScript); + const std::regex test_print("I \\(" TIMESTAMP "\\) test: info", std::regex::ECMAScript); ESP_LOGI(TEST_TAG, "info"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -162,7 +176,7 @@ TEST_CASE("info log level") TEST_CASE("warn log level") { PrintFixture fix(ESP_LOG_WARN); - const std::regex test_print("W \\([0-9]*\\) test: warn", std::regex::ECMAScript); + const std::regex test_print("W \\(" TIMESTAMP "\\) test: warn", std::regex::ECMAScript); ESP_LOGW(TEST_TAG, "warn"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -171,7 +185,7 @@ TEST_CASE("warn log level") TEST_CASE("error log level") { PrintFixture fix(ESP_LOG_ERROR); - const std::regex test_print("E \\([0-9]*\\) test: error", std::regex::ECMAScript); + const std::regex test_print("E \\(" TIMESTAMP "\\) test: error", std::regex::ECMAScript); ESP_LOGE(TEST_TAG, "error"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -181,7 +195,7 @@ TEST_CASE("error log level") TEST_CASE("changing log level") { PrintFixture fix(ESP_LOG_INFO); - const std::regex test_print("I \\([0-9]*\\) test: must indeed be printed", std::regex::ECMAScript); + const std::regex test_print("I \\(" TIMESTAMP "\\) test: must indeed be printed", std::regex::ECMAScript); ESP_LOGI(TEST_TAG, "must indeed be printed"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -208,7 +222,7 @@ TEST_CASE("log buffer") 0x11, 0x12, 0x13, 0x14, 0x15, 0x16, 0x17, 0x18, }; ESP_LOG_BUFFER_HEX(TEST_TAG, buffer, sizeof(buffer)); - const std::regex buffer_regex("I \\([0-9]*\\) test: 01 02 03 04 05 06 07 08 11 12 13 14 15 16 17 18", std::regex::ECMAScript); + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: 01 02 03 04 05 06 07 08 11 12 13 14 15 16 17 18", std::regex::ECMAScript); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex)); } @@ -219,7 +233,7 @@ TEST_CASE("log bytes > 127") 0xff, 0x80, }; ESP_LOG_BUFFER_HEX(TEST_TAG, buffer, sizeof(buffer)); - const std::regex buffer_regex("I \\([0-9]*\\) test: ff 80", std::regex::ECMAScript); + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: ff 80", std::regex::ECMAScript); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex)); } @@ -227,11 +241,11 @@ TEST_CASE("log buffer char") { PrintFixture fix(ESP_LOG_INFO); const char g[] = "The way to get started is to quit talking and begin doing. - Walt Disney"; - const std::regex buffer_regex("I \\([0-9]*\\) test: The way to get s.*\n\ -.*I \\([0-9]*\\) test: tarted is to qui.*\n\ -.*I \\([0-9]*\\) test: t talking and be.*\n\ -.*I \\([0-9]*\\) test: gin doing. - Wal.*\n\ -.*I \\([0-9]*\\) test: t Disney", std::regex::ECMAScript); + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: The way to get s.*\n\ +.*I \\(" TIMESTAMP "\\) test: tarted is to qui.*\n\ +.*I \\(" TIMESTAMP "\\) test: t talking and be.*\n\ +.*I \\(" TIMESTAMP "\\) test: gin doing. - Wal.*\n\ +.*I \\(" TIMESTAMP "\\) test: t Disney", std::regex::ECMAScript); ESP_LOG_BUFFER_CHAR(TEST_TAG, g, sizeof(g)); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex) == true); } @@ -244,7 +258,7 @@ TEST_CASE("log buffer dump") 0xff, 0xfe, 0xfd, 0xfc, 0xfb, 0xfa, 0xf9, 0xf8 }; ESP_LOG_BUFFER_HEXDUMP(TEST_TAG, buffer, sizeof(buffer), ESP_LOG_INFO); - const std::regex buffer_regex("I \\([0-9]*\\) test: 0x[0-9a-f]+\\s+" + const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: 0x[0-9a-f]+\\s+" "00 00 00 00 05 06 07 08 ff fe fd fc fb fa f9 f8 " "\\s+|[\\.]{16}|", std::regex::ECMAScript); CHECK(regex_search(fix.get_print_buffer_string(), buffer_regex)); @@ -262,7 +276,7 @@ TEST_CASE("rom printf") TEST_CASE("early verbose log level") { PutcFixture fix; - const std::regex test_print("V \\([0-9]*\\) test: verbose", std::regex::ECMAScript); + const std::regex test_print("V \\(" EARLY_TIMESTAMP "\\) test: verbose", std::regex::ECMAScript); ESP_EARLY_LOGV(TEST_TAG, "verbose"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -271,7 +285,7 @@ TEST_CASE("early verbose log level") TEST_CASE("early debug log level") { PutcFixture fix; - const std::regex test_print("D \\([0-9]*\\) test: debug", std::regex::ECMAScript); + const std::regex test_print("D \\(" EARLY_TIMESTAMP "\\) test: debug", std::regex::ECMAScript); ESP_EARLY_LOGD(TEST_TAG, "debug"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -280,7 +294,7 @@ TEST_CASE("early debug log level") TEST_CASE("early info log level") { PutcFixture fix; - const std::regex test_print("I \\([0-9]*\\) test: info", std::regex::ECMAScript); + const std::regex test_print("I \\(" EARLY_TIMESTAMP "\\) test: info", std::regex::ECMAScript); ESP_EARLY_LOGI(TEST_TAG, "info"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -289,7 +303,7 @@ TEST_CASE("early info log level") TEST_CASE("early warn log level") { PutcFixture fix; - const std::regex test_print("W \\([0-9]*\\) test: warn", std::regex::ECMAScript); + const std::regex test_print("W \\(" EARLY_TIMESTAMP "\\) test: warn", std::regex::ECMAScript); ESP_EARLY_LOGW(TEST_TAG, "warn"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -298,7 +312,7 @@ TEST_CASE("early warn log level") TEST_CASE("early error log level") { PutcFixture fix; - const std::regex test_print("E \\([0-9]*\\) test: error", std::regex::ECMAScript); + const std::regex test_print("E \\(" EARLY_TIMESTAMP "\\) test: error", std::regex::ECMAScript); ESP_EARLY_LOGE(TEST_TAG, "error"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -308,7 +322,7 @@ TEST_CASE("early error log level") TEST_CASE("changing early log level") { PutcFixture fix(ESP_LOG_INFO); - const std::regex test_print("I \\([0-9]*\\) test: must indeed be printed", std::regex::ECMAScript); + const std::regex test_print("I \\(" EARLY_TIMESTAMP "\\) test: must indeed be printed", std::regex::ECMAScript); ESP_EARLY_LOGI(TEST_TAG, "must indeed be printed"); CHECK(regex_search(fix.get_print_buffer_string(), test_print) == true); @@ -374,3 +388,19 @@ TEST_CASE("esp_log_util_cvt") CHECK(strcmp(buf, "073f") == 0); memset(buf, 0, sizeof(buf)); } + +TEST_CASE("esp_log_timestamp_str") +{ + char buffer[64]; + bool critical = true; + uint64_t timestamp_ms = esp_log_timestamp64(critical); + esp_log_timestamp_str(critical, timestamp_ms, buffer); + const std::regex test_print(EARLY_TIMESTAMP, std::regex::ECMAScript); + CHECK(regex_search(string(buffer), test_print) == true); + + critical = false; + timestamp_ms = esp_log_timestamp64(critical); + esp_log_timestamp_str(critical, timestamp_ms, buffer); + const std::regex test_print2(TIMESTAMP, std::regex::ECMAScript); + CHECK(regex_search(string(buffer), test_print2) == true); +} diff --git a/components/log/host_test/log_test/pytest_log_linux.py b/components/log/host_test/log_test/pytest_log_linux.py index 07078c4699..0425762aa4 100644 --- a/components/log/host_test/log_test/pytest_log_linux.py +++ b/components/log/host_test/log_test/pytest_log_linux.py @@ -8,6 +8,7 @@ from pytest_embedded import Dut @pytest.mark.host_test @pytest.mark.parametrize('config', [ 'default', + 'system_timestamp' 'tag_level_linked_list', 'tag_level_linked_list_and_array_cache', 'tag_level_none', diff --git a/components/log/host_test/log_test/sdkconfig.ci.system_timestamp b/components/log/host_test/log_test/sdkconfig.ci.system_timestamp new file mode 100644 index 0000000000..215a8e71dd --- /dev/null +++ b/components/log/host_test/log_test/sdkconfig.ci.system_timestamp @@ -0,0 +1 @@ +CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y diff --git a/components/log/include/esp_log.h b/components/log/include/esp_log.h index 7d11348614..8d11d9ca94 100644 --- a/components/log/include/esp_log.h +++ b/components/log/include/esp_log.h @@ -9,11 +9,12 @@ #include #include #include -#include "esp_log_level.h" #include "sdkconfig.h" #include "esp_rom_sys.h" #include "esp_log_level.h" +#include "esp_log_color.h" #include "esp_log_buffer.h" +#include "esp_log_timestamp.h" #ifdef __cplusplus extern "C" { @@ -37,45 +38,6 @@ typedef int (*vprintf_like_t)(const char *, va_list); */ vprintf_like_t esp_log_set_vprintf(vprintf_like_t func); -/** - * @brief Function which returns timestamp to be used in log output - * - * This function is used in expansion of ESP_LOGx macros. - * In the 2nd stage bootloader, and at early application startup stage - * this function uses CPU cycle counter as time source. Later when - * FreeRTOS scheduler start running, it switches to FreeRTOS tick count. - * - * For now, we ignore millisecond counter overflow. - * - * @return timestamp, in milliseconds - */ -uint32_t esp_log_timestamp(void); - -/** - * @brief Function which returns system timestamp to be used in log output - * - * This function is used in expansion of ESP_LOGx macros to print - * the system time as "HH:MM:SS.sss". The system time is initialized to - * 0 on startup, this can be set to the correct time with an SNTP sync, - * or manually with standard POSIX time functions. - * - * Currently, this will not get used in logging from binary blobs - * (i.e. Wi-Fi & Bluetooth libraries), these will still print the RTOS tick time. - * - * @return timestamp, in "HH:MM:SS.sss" - */ -char* esp_log_system_timestamp(void); - -/** - * @brief Function which returns timestamp to be used in log output - * - * This function uses HW cycle counter and does not depend on OS, - * so it can be safely used after application crash. - * - * @return timestamp, in milliseconds - */ -uint32_t esp_log_early_timestamp(void); - /** * @brief Write message into the log * @@ -97,31 +59,6 @@ void esp_log_writev(esp_log_level_t level, const char* tag, const char* format, /** @cond */ -#if CONFIG_LOG_COLORS -#define LOG_COLOR_BLACK "30" -#define LOG_COLOR_RED "31" -#define LOG_COLOR_GREEN "32" -#define LOG_COLOR_BROWN "33" -#define LOG_COLOR_BLUE "34" -#define LOG_COLOR_PURPLE "35" -#define LOG_COLOR_CYAN "36" -#define LOG_COLOR(COLOR) "\033[0;" COLOR "m" -#define LOG_BOLD(COLOR) "\033[1;" COLOR "m" -#define LOG_RESET_COLOR "\033[0m" -#define LOG_COLOR_E LOG_COLOR(LOG_COLOR_RED) -#define LOG_COLOR_W LOG_COLOR(LOG_COLOR_BROWN) -#define LOG_COLOR_I LOG_COLOR(LOG_COLOR_GREEN) -#define LOG_COLOR_D -#define LOG_COLOR_V -#else //CONFIG_LOG_COLORS -#define LOG_COLOR_E -#define LOG_COLOR_W -#define LOG_COLOR_I -#define LOG_COLOR_D -#define LOG_COLOR_V -#define LOG_RESET_COLOR -#endif //CONFIG_LOG_COLORS - #define LOG_FORMAT(letter, format) LOG_COLOR_ ## letter #letter " (%" PRIu32 ") %s: " format LOG_RESET_COLOR "\n" #define LOG_SYSTEM_TIME_FORMAT(letter, format) LOG_COLOR_ ## letter #letter " (%s) %s: " format LOG_RESET_COLOR "\n" diff --git a/components/log/include/esp_log_color.h b/components/log/include/esp_log_color.h new file mode 100644 index 0000000000..483d634ea6 --- /dev/null +++ b/components/log/include/esp_log_color.h @@ -0,0 +1,108 @@ +/* + * SPDX-FileCopyrightText: 2015-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include "sdkconfig.h" + +#ifdef __cplusplus +extern "C" { +#endif + +/** @cond */ +// ANSI Color Codes: +// Macros for defining foreground colors (text). +#define LOG_ANSI_COLOR_BLACK "30" +#define LOG_ANSI_COLOR_RED "31" +#define LOG_ANSI_COLOR_GREEN "32" +#define LOG_ANSI_COLOR_YELLOW "33" +#define LOG_ANSI_COLOR_BLUE "34" +#define LOG_ANSI_COLOR_MAGENTA "35" +#define LOG_ANSI_COLOR_CYAN "36" +#define LOG_ANSI_COLOR_WHITE "37" +#define LOG_ANSI_COLOR_DEFAULT "39" +// Macros for defining background colors. +#define LOG_ANSI_COLOR_BG_BLACK "40" +#define LOG_ANSI_COLOR_BG_RED "41" +#define LOG_ANSI_COLOR_BG_GREEN "42" +#define LOG_ANSI_COLOR_BG_YELLOW "43" +#define LOG_ANSI_COLOR_BG_BLUE "44" +#define LOG_ANSI_COLOR_BG_MAGENTA "45" +#define LOG_ANSI_COLOR_BG_CYAN "46" +#define LOG_ANSI_COLOR_BG_WHITE "47" +#define LOG_ANSI_COLOR_BG_DEFAULT "49" +// Macros for defining text styles like bold, italic, and underline. +#define LOG_ANSI_COLOR_STYLE_RESET "0" +#define LOG_ANSI_COLOR_STYLE_BOLD "1" +#define LOG_ANSI_COLOR_STYLE_ITALIC "3" +#define LOG_ANSI_COLOR_STYLE_UNDERLINE "4" +// Macros that form the starting sequence for setting the text color, background color, and reset all. +#define LOG_ANSI_COLOR(TEXT_COLOR) "\033[" TEXT_COLOR "m" +#define LOG_ANSI_COLOR_BG(BG_COLOR) "\033[" BG_COLOR "m" +#define LOG_ANSI_COLOR_RESET "\033[" LOG_ANSI_COLOR_STYLE_RESET "m" +// Macros that form the starting sequence for text color + style + background colors +#define LOG_ANSI_COLOR_REGULAR(COLOR) LOG_ANSI_COLOR(LOG_ANSI_COLOR_STYLE_RESET ";" COLOR) +#define LOG_ANSI_COLOR_BOLD(COLOR) LOG_ANSI_COLOR(LOG_ANSI_COLOR_STYLE_BOLD ";" COLOR) +#define LOG_ANSI_COLOR_ITALIC(COLOR) LOG_ANSI_COLOR(LOG_ANSI_COLOR_STYLE_ITALIC ";" COLOR) +#define LOG_ANSI_COLOR_UNDERLINE(COLOR) LOG_ANSI_COLOR(LOG_ANSI_COLOR_STYLE_UNDERLINE ";" COLOR) +#define LOG_ANSI_COLOR_BACKGROUND(TEXT_COLOR, BG_COLOR) LOG_ANSI_COLOR(TEXT_COLOR ";" BG_COLOR) +#define LOG_ANSI_COLOR_REGULAR_BACKGROUND(TEXT_COLOR, BG_COLOR) LOG_ANSI_COLOR_REGULAR(TEXT_COLOR ";" BG_COLOR) +#define LOG_ANSI_COLOR_BOLD_BACKGROUND(TEXT_COLOR, BG_COLOR) LOG_ANSI_COLOR_BOLD(TEXT_COLOR ";" BG_COLOR) +#define LOG_ANSI_COLOR_ITALIC_BACKGROUND(TEXT_COLOR, BG_COLOR) LOG_ANSI_COLOR_ITALIC(TEXT_COLOR ";" BG_COLOR) +#define LOG_ANSI_COLOR_UNDERLINE_BACKGROUND(TEXT_COLOR, BG_COLOR) LOG_ANSI_COLOR_UNDERLINE(TEXT_COLOR ";" BG_COLOR) +#define LOG_ANSI_COLOR_FORMAT(TEXT_STYLE, TEXT_COLOR, BG_COLOR) LOG_ANSI_COLOR(TEXT_STYLE ";" TEXT_COLOR ";" BG_COLOR) + +/** + * Usage example of ANSI color for logs: + * + * The text is yellow and no style. + * printf(LOG_ANSI_COLOR(LOG_ANSI_COLOR_YELLOW) "%s" LOG_ANSI_COLOR_RESET "\n", text_str); + * + * The text is red and no style on a green background. + * printf(LOG_ANSI_COLOR_REGULAR_BACKGROUND(LOG_ANSI_COLOR_RED, LOG_ANSI_COLOR_BG_GREEN) "%s" LOG_ANSI_COLOR_RESET "\n", text_str); + * + * Note that if LOG_ANSI_COLOR_RESET is not sent, the settings are retained until the following setting. + * + * The LOG_ANSI_COLOR_FORMAT macro is more flexible than others. It does not use the reset command, which means that + * this macro can combine the style with the previous settings. + * The text is white and bold on a blue background. + * printf(LOG_ANSI_COLOR_FORMAT(LOG_ANSI_COLOR_STYLE_BOLD, LOG_ANSI_COLOR_WHITE, LOG_ANSI_COLOR_BG_BLUE) "%s" LOG_ANSI_COLOR_RESET "\n", text_str); + */ + +#if (!BOOTLOADER_BUILD && CONFIG_LOG_COLORS) || (BOOTLOADER_BUILD && CONFIG_BOOTLOADER_LOG_COLORS) +#define LOG_COLOR_BLACK LOG_ANSI_COLOR_BLACK +#define LOG_COLOR_RED LOG_ANSI_COLOR_RED +#define LOG_COLOR_GREEN LOG_ANSI_COLOR_GREEN +#define LOG_COLOR_BROWN LOG_ANSI_COLOR_YELLOW +#define LOG_COLOR_YELLOW LOG_ANSI_COLOR_YELLOW +#define LOG_COLOR_BLUE LOG_ANSI_COLOR_BLUE +#define LOG_COLOR_PURPLE LOG_ANSI_COLOR_MAGENTA +#define LOG_COLOR_MAGENTA LOG_ANSI_COLOR_MAGENTA +#define LOG_COLOR_CYAN LOG_ANSI_COLOR_CYAN +#define LOG_COLOR_WHITE LOG_ANSI_COLOR_WHITE +#define LOG_COLOR(COLOR) LOG_ANSI_COLOR_REGULAR(COLOR) +#define LOG_BOLD(COLOR) LOG_ANSI_COLOR_BOLD(COLOR) +#define LOG_ITALIC(COLOR) LOG_ANSI_COLOR_ITALIC(COLOR) +#define LOG_UNDERLINE(COLOR) LOG_ANSI_COLOR_UNDERLINE(COLOR) +#define LOG_RESET_COLOR LOG_ANSI_COLOR_RESET +#define LOG_COLOR_E LOG_ANSI_COLOR_REGULAR(LOG_COLOR_RED) +#define LOG_COLOR_W LOG_ANSI_COLOR_REGULAR(LOG_COLOR_YELLOW) +#define LOG_COLOR_I LOG_ANSI_COLOR_REGULAR(LOG_COLOR_GREEN) +#define LOG_COLOR_D "" +#define LOG_COLOR_V "" +#else +#define LOG_RESET_COLOR "" +#define LOG_COLOR_E "" +#define LOG_COLOR_W "" +#define LOG_COLOR_I "" +#define LOG_COLOR_D "" +#define LOG_COLOR_V "" +#endif +/** @endcond */ + +#ifdef __cplusplus +} +#endif diff --git a/components/log/include/esp_log_timestamp.h b/components/log/include/esp_log_timestamp.h new file mode 100644 index 0000000000..dfefbcdbb3 --- /dev/null +++ b/components/log/include/esp_log_timestamp.h @@ -0,0 +1,56 @@ +/* + * SPDX-FileCopyrightText: 2015-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Function which returns timestamp to be used in log output + * + * This function is used in expansion of ESP_LOGx macros. + * In the 2nd stage bootloader, and at early application startup stage + * this function uses CPU cycle counter as time source. Later when + * FreeRTOS scheduler start running, it switches to FreeRTOS tick count. + * + * For now, we ignore millisecond counter overflow. + * + * @return timestamp, in milliseconds + */ +uint32_t esp_log_timestamp(void); + +/** + * @brief Function which returns system timestamp to be used in log output + * + * This function is used in expansion of ESP_LOGx macros to print + * the system time as "HH:MM:SS.sss". The system time is initialized to + * 0 on startup, this can be set to the correct time with an SNTP sync, + * or manually with standard POSIX time functions. + * + * Currently, this will not get used in logging from binary blobs + * (i.e. Wi-Fi & Bluetooth libraries), these will still print the RTOS tick time. + * + * @return timestamp, in "HH:MM:SS.sss" + */ +char* esp_log_system_timestamp(void); + +/** + * @brief Function which returns timestamp to be used in log output + * + * This function uses HW cycle counter and does not depend on OS, + * so it can be safely used after application crash. + * + * @return timestamp, in milliseconds + */ +uint32_t esp_log_early_timestamp(void); + +#ifdef __cplusplus +} +#endif diff --git a/components/log/include/esp_private/log_timestamp.h b/components/log/include/esp_private/log_timestamp.h new file mode 100644 index 0000000000..7312d332c6 --- /dev/null +++ b/components/log/include/esp_private/log_timestamp.h @@ -0,0 +1,57 @@ +/* + * SPDX-FileCopyrightText: 2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Get the timestamp in milliseconds for logging. + * + * This function retrieves the timestamp in milliseconds for logging purposes. + * + * @param[in] critical Flag indicating whether the timestamp is needed for a critical log. + * If this flag is true, it means the function is called in one of the following states: + * - early stage, when the Freertos scheduler is not running, + * - ISR, + * - CACHE is disabled. + * + * If the critical flag is set then uint32 timestamp is returned due to cpu ticks being used for this case. + * For some applications this uint32 timestamp may overflow after 4294967295/1000/86400 = 49 days of operation. + * + * @return The uint64 timestamp in milliseconds. + */ +uint64_t esp_log_timestamp64(bool critical); + +/** + * @brief Convert the uint64 timestamp to a string representation. + * + * This function converts the uint64 timestamp in milliseconds to a string representation. + * The string representation depends on Kconfig options: + * - Milliseconds since boot, + * - Date and time, + * - Time. + * + * @param[in] critical Flag indicating whether the timestamp is critical. If this flag is true, + * it means the function is called in one of the following states: + * - early stage, when the Freertos scheduler is not running, + * - ISR, + * - CACHE is disabled. + * @param[in] timestamp_ms The timestamp to convert, in milliseconds. + * @param[out] buffer Pointer to the buffer where the string representation will be stored. + * + * @return Pointer to the buffer containing the string representation of the timestamp. + */ +char* esp_log_timestamp_str(bool critical, uint64_t timestamp_ms, char* buffer); + +#ifdef __cplusplus +} +#endif diff --git a/components/log/linker.lf b/components/log/linker.lf index 10627148ff..5339affc8c 100644 --- a/components/log/linker.lf +++ b/components/log/linker.lf @@ -2,8 +2,6 @@ archive: liblog.a entries: log_write:esp_log_write (noflash) - log_freertos:esp_log_timestamp (noflash) - log_freertos:esp_log_early_timestamp (noflash) - log_freertos:esp_log_impl_lock (noflash) - log_freertos:esp_log_impl_lock_timeout (noflash) - log_freertos:esp_log_impl_unlock (noflash) + log_timestamp:esp_log_timestamp (noflash) + log_timestamp:esp_log_early_timestamp (noflash) + log_lock (noflash) diff --git a/components/log/log_freertos.c b/components/log/log_freertos.c deleted file mode 100644 index b45da16d26..0000000000 --- a/components/log/log_freertos.c +++ /dev/null @@ -1,121 +0,0 @@ -/* - * SPDX-FileCopyrightText: 2015-2021 Espressif Systems (Shanghai) CO LTD - * - * SPDX-License-Identifier: Apache-2.0 - */ - -#include -#include -#include -#include "freertos/FreeRTOS.h" -#include "freertos/task.h" -#include "freertos/semphr.h" -#include "esp_cpu.h" // for esp_cpu_get_cycle_count() -#include "esp_compiler.h" -#include "esp_log.h" -#include "esp_private/log_lock.h" - -// Maximum time to wait for the mutex in a logging statement. -// -// We don't expect this to happen in most cases, as contention is low. The most likely case is if a -// log function is called from an ISR (technically caller should use the ISR-friendly logging macros but -// possible they use the normal one instead and disable the log type by tag). -#define MAX_MUTEX_WAIT_MS 10 -#define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS) - -static SemaphoreHandle_t s_log_mutex = NULL; - -void esp_log_impl_lock(void) -{ - if (unlikely(!s_log_mutex)) { - s_log_mutex = xSemaphoreCreateMutex(); - } - if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { - return; - } - xSemaphoreTake(s_log_mutex, portMAX_DELAY); -} - -bool esp_log_impl_lock_timeout(void) -{ - if (unlikely(!s_log_mutex)) { - s_log_mutex = xSemaphoreCreateMutex(); - } - if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { - return true; - } - return xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS) == pdTRUE; -} - -void esp_log_impl_unlock(void) -{ - if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { - return; - } - xSemaphoreGive(s_log_mutex); -} - -char *esp_log_system_timestamp(void) -{ - static char buffer[18] = {0}; - static _lock_t bufferLock = 0; - - if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) { - uint32_t timestamp = esp_log_early_timestamp(); - for (uint8_t i = 0; i < sizeof(buffer); i++) { - if ((timestamp > 0) || (i == 0)) { - for (uint8_t j = sizeof(buffer) - 1; j > 0; j--) { - buffer[j] = buffer[j - 1]; - } - buffer[0] = (char)(timestamp % 10) + '0'; - timestamp /= 10; - } else { - buffer[i] = 0; - break; - } - } - return buffer; - } else { - struct timeval tv; - struct tm timeinfo; - - gettimeofday(&tv, NULL); - localtime_r(&tv.tv_sec, &timeinfo); - - _lock_acquire(&bufferLock); - snprintf(buffer, sizeof(buffer), - "%02d:%02d:%02d.%03ld", - timeinfo.tm_hour, - timeinfo.tm_min, - timeinfo.tm_sec, - tv.tv_usec / 1000); - _lock_release(&bufferLock); - - return buffer; - } -} - -uint32_t esp_log_timestamp(void) -{ - if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { - return esp_log_early_timestamp(); - } - static uint32_t base = 0; - if (base == 0 && xPortGetCoreID() == 0) { - base = esp_log_early_timestamp(); - } - TickType_t tick_count = xPortInIsrContext() ? xTaskGetTickCountFromISR() : xTaskGetTickCount(); - return base + tick_count * (1000 / configTICK_RATE_HZ); -} - -/* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */ -uint32_t esp_log_early_timestamp(void) -{ -#if CONFIG_IDF_TARGET_ESP32 - /* ESP32 ROM stores separate clock rate values for each CPU, but we want the PRO CPU value always */ - extern uint32_t g_ticks_per_us_pro; - return esp_cpu_get_cycle_count() / (g_ticks_per_us_pro * 1000); -#else - return esp_cpu_get_cycle_count() / (esp_rom_get_cpu_ticks_per_us() * 1000); -#endif -} diff --git a/components/log/log_linux.c b/components/log/src/linux/log_lock.c similarity index 61% rename from components/log/log_linux.c rename to components/log/src/linux/log_lock.c index c27b1e592e..18bbd1cc93 100644 --- a/components/log/log_linux.c +++ b/components/log/src/linux/log_lock.c @@ -5,9 +5,7 @@ */ #include -#include #include -#include #include "esp_private/log_lock.h" static pthread_mutex_t mutex1 = PTHREAD_MUTEX_INITIALIZER; @@ -27,12 +25,3 @@ void esp_log_impl_unlock(void) { assert(pthread_mutex_unlock(&mutex1) == 0); } - -uint32_t esp_log_timestamp(void) -{ - struct timespec current_time; - int result = clock_gettime(CLOCK_MONOTONIC, ¤t_time); - assert(result == 0); - uint32_t milliseconds = current_time.tv_sec * 1000 + current_time.tv_nsec / 1000000; - return milliseconds; -} diff --git a/components/log/src/linux/log_timestamp.c b/components/log/src/linux/log_timestamp.c new file mode 100644 index 0000000000..04fc51d433 --- /dev/null +++ b/components/log/src/linux/log_timestamp.c @@ -0,0 +1,20 @@ +/* + * SPDX-FileCopyrightText: 2010-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include "esp_log_timestamp.h" + +uint32_t esp_log_early_timestamp(void) +{ + struct timespec current_time; + int result = clock_gettime(CLOCK_MONOTONIC, ¤t_time); + assert(result == 0); + uint32_t milliseconds = current_time.tv_sec * 1000 + current_time.tv_nsec / 1000000; + return milliseconds; +} + +uint32_t esp_log_timestamp(void) __attribute__((alias("esp_log_early_timestamp"))); diff --git a/components/log/src/log_timestamp_common.c b/components/log/src/log_timestamp_common.c new file mode 100644 index 0000000000..ba9521908f --- /dev/null +++ b/components/log/src/log_timestamp_common.c @@ -0,0 +1,129 @@ +/* + * SPDX-FileCopyrightText: 2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include +#include "esp_log_timestamp.h" +#include "esp_private/log_util.h" +#include "esp_private/log_timestamp.h" +#include "sdkconfig.h" + +#if !BOOTLOADER_BUILD +#include +#include "freertos/FreeRTOS.h" +#include "freertos/task.h" + +char *esp_log_system_timestamp(void) +{ + static char buffer[18] = {0}; + static _lock_t bufferLock = 0; + +#if CONFIG_IDF_TARGET_LINUX + const bool early_log = false; +#else + const bool early_log = xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED; +#endif + if (early_log) { + uint32_t timestamp = esp_log_early_timestamp(); + for (uint8_t i = 0; i < sizeof(buffer); i++) { + if ((timestamp > 0) || (i == 0)) { + for (uint8_t j = sizeof(buffer) - 1; j > 0; j--) { + buffer[j] = buffer[j - 1]; + } + buffer[0] = (char)(timestamp % 10) + '0'; + timestamp /= 10; + } else { + buffer[i] = 0; + break; + } + } + } else { + struct timeval tv; + struct tm timeinfo; + + gettimeofday(&tv, NULL); + localtime_r(&tv.tv_sec, &timeinfo); + + _lock_acquire(&bufferLock); + unsigned msec = tv.tv_usec / 1000; + snprintf(buffer, sizeof(buffer), + "%02d:%02d:%02d.%03d", + timeinfo.tm_hour, + timeinfo.tm_min, + timeinfo.tm_sec, + msec); + _lock_release(&bufferLock); + } + return buffer; +} +#endif // !BOOTLOADER_BUILD + +uint64_t esp_log_timestamp64(bool critical) +{ + uint64_t timestamp_ms; +#if CONFIG_BOOTLOADER_LOG_TIMESTAMP_SOURCE_NONE || CONFIG_LOG_TIMESTAMP_SOURCE_NONE + (void) critical; + timestamp_ms = 0; +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM || CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + if (critical) { + timestamp_ms = esp_log_early_timestamp(); + } else { +#if CONFIG_IDF_TARGET_LINUX + struct timespec tv; + int result = clock_gettime(CLOCK_MONOTONIC, &tv); + assert(result == 0); + timestamp_ms = tv.tv_sec * 1000 + tv.tv_nsec / 1000000; +#else + struct timeval tv; + gettimeofday(&tv, NULL); + timestamp_ms = tv.tv_sec * 1000 + tv.tv_usec / 1000; +#endif + } +#else + (void) critical; + timestamp_ms = esp_log_timestamp(); +#endif + return timestamp_ms; +} + +char* esp_log_timestamp_str(bool critical, uint64_t timestamp_ms, char* buffer) +{ + char* out_buffer = buffer; +#if CONFIG_BOOTLOADER_LOG_TIMESTAMP_SOURCE_NONE || CONFIG_LOG_TIMESTAMP_SOURCE_NONE + (void)critical; + *buffer = '\0'; +#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM || CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + if (critical) { + esp_log_util_cvt_dec(timestamp_ms, 0, buffer); + } else { + struct tm timeinfo; + time_t sec = timestamp_ms / 1000; + uint64_t msec = timestamp_ms % 1000; + localtime_r(&sec, &timeinfo); +#if CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + // it takes 22 bytes to output it in the format: "YY-MM-DD HH:MM:SS.sss" + buffer += esp_log_util_cvt_dec(timeinfo.tm_year, 2, buffer); + *buffer++ = '-'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_mon + 1, 2, buffer); + *buffer++ = '-'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_mday, 2, buffer); + *buffer++ = ' '; +#endif // CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM_FULL + buffer += esp_log_util_cvt_dec(timeinfo.tm_hour, 2, buffer); + *buffer++ = ':'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_min, 2, buffer); + *buffer++ = ':'; + buffer += esp_log_util_cvt_dec(timeinfo.tm_sec, 2, buffer); + *buffer++ = '.'; + esp_log_util_cvt_dec(msec, 3, buffer); // (ms) + } +#else + (void)critical; + esp_log_util_cvt_dec(timestamp_ms, 0, buffer); +#endif + return out_buffer; +} diff --git a/components/log/src/noos/log_lock.c b/components/log/src/noos/log_lock.c new file mode 100644 index 0000000000..0e7acce0ad --- /dev/null +++ b/components/log/src/noos/log_lock.c @@ -0,0 +1,28 @@ +/* + * SPDX-FileCopyrightText: 2019-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include "esp_private/log_lock.h" + +static int s_lock = 0; + +void esp_log_impl_lock(void) +{ + assert(s_lock == 0); + s_lock = 1; +} + +bool esp_log_impl_lock_timeout(void) +{ + esp_log_impl_lock(); + return true; +} + +void esp_log_impl_unlock(void) +{ + assert(s_lock == 1); + s_lock = 0; +} diff --git a/components/log/log_noos.c b/components/log/src/noos/log_timestamp.c similarity index 50% rename from components/log/log_noos.c rename to components/log/src/noos/log_timestamp.c index ae8ff62841..4f1f88e352 100644 --- a/components/log/log_noos.c +++ b/components/log/src/noos/log_timestamp.c @@ -1,33 +1,12 @@ /* - * SPDX-FileCopyrightText: 2019-2021 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2019-2024 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Apache-2.0 */ -#include -#include "esp_private/log_lock.h" #include "esp_rom_sys.h" #include "esp_cpu.h" - -static int s_lock = 0; - -void esp_log_impl_lock(void) -{ - assert(s_lock == 0); - s_lock = 1; -} - -bool esp_log_impl_lock_timeout(void) -{ - esp_log_impl_lock(); - return true; -} - -void esp_log_impl_unlock(void) -{ - assert(s_lock == 1); - s_lock = 0; -} +#include "esp_log_timestamp.h" /* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */ uint32_t esp_log_early_timestamp(void) diff --git a/components/log/src/os/log_lock.c b/components/log/src/os/log_lock.c new file mode 100644 index 0000000000..8a8a5febdf --- /dev/null +++ b/components/log/src/os/log_lock.c @@ -0,0 +1,51 @@ +/* + * SPDX-FileCopyrightText: 2015-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "freertos/FreeRTOS.h" +#include "freertos/task.h" +#include "freertos/semphr.h" +#include "esp_compiler.h" +#include "esp_private/log_lock.h" + +// Maximum time to wait for the mutex in a logging statement. +// +// We don't expect this to happen in most cases, as contention is low. The most likely case is if a +// log function is called from an ISR (technically caller should use the ISR-friendly logging macros but +// possible they use the normal one instead and disable the log type by tag). +#define MAX_MUTEX_WAIT_MS 10 +#define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS) + +static SemaphoreHandle_t s_log_mutex = NULL; + +void esp_log_impl_lock(void) +{ + if (unlikely(!s_log_mutex)) { + s_log_mutex = xSemaphoreCreateMutex(); + } + if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { + return; + } + xSemaphoreTake(s_log_mutex, portMAX_DELAY); +} + +bool esp_log_impl_lock_timeout(void) +{ + if (unlikely(!s_log_mutex)) { + s_log_mutex = xSemaphoreCreateMutex(); + } + if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { + return true; + } + return xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS) == pdTRUE; +} + +void esp_log_impl_unlock(void) +{ + if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { + return; + } + xSemaphoreGive(s_log_mutex); +} diff --git a/components/log/src/os/log_timestamp.c b/components/log/src/os/log_timestamp.c new file mode 100644 index 0000000000..484487e96d --- /dev/null +++ b/components/log/src/os/log_timestamp.c @@ -0,0 +1,37 @@ +/* + * SPDX-FileCopyrightText: 2015-2024 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include "freertos/FreeRTOS.h" +#include "freertos/task.h" +#include "esp_cpu.h" // for esp_cpu_get_cycle_count() +#include "esp_compiler.h" +#include "esp_log_timestamp.h" +#include "sdkconfig.h" + +uint32_t esp_log_timestamp(void) +{ + if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) { + return esp_log_early_timestamp(); + } + static uint32_t base = 0; + if (base == 0 && xPortGetCoreID() == 0) { + base = esp_log_early_timestamp(); + } + TickType_t tick_count = xPortInIsrContext() ? xTaskGetTickCountFromISR() : xTaskGetTickCount(); + return base + tick_count * (1000 / configTICK_RATE_HZ); +} + +/* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */ +uint32_t esp_log_early_timestamp(void) +{ +#if CONFIG_IDF_TARGET_ESP32 + /* ESP32 ROM stores separate clock rate values for each CPU, but we want the PRO CPU value always */ + extern uint32_t g_ticks_per_us_pro; + return esp_cpu_get_cycle_count() / (g_ticks_per_us_pro * 1000); +#else + return esp_cpu_get_cycle_count() / (esp_rom_get_cpu_ticks_per_us() * 1000); +#endif +} diff --git a/docs/doxygen/Doxyfile b/docs/doxygen/Doxyfile index 4f5211532a..d54d9deb76 100644 --- a/docs/doxygen/Doxyfile +++ b/docs/doxygen/Doxyfile @@ -271,6 +271,8 @@ INPUT = \ $(PROJECT_PATH)/components/log/include/esp_log.h \ $(PROJECT_PATH)/components/log/include/esp_log_level.h \ $(PROJECT_PATH)/components/log/include/esp_log_buffer.h \ + $(PROJECT_PATH)/components/log/include/esp_log_timestamp.h \ + $(PROJECT_PATH)/components/log/include/esp_log_color.h \ $(PROJECT_PATH)/components/lwip/include/apps/esp_sntp.h \ $(PROJECT_PATH)/components/lwip/include/apps/ping/ping_sock.h \ $(PROJECT_PATH)/components/mbedtls/esp_crt_bundle/include/esp_crt_bundle.h \ diff --git a/docs/en/api-reference/system/log.rst b/docs/en/api-reference/system/log.rst index 9fb63a67e6..452161ddb1 100644 --- a/docs/en/api-reference/system/log.rst +++ b/docs/en/api-reference/system/log.rst @@ -153,3 +153,5 @@ API Reference .. include-build-file:: inc/esp_log.inc .. include-build-file:: inc/esp_log_level.inc .. include-build-file:: inc/esp_log_buffer.inc +.. include-build-file:: inc/esp_log_timestamp.inc +.. include-build-file:: inc/esp_log_color.inc diff --git a/docs/zh_CN/api-reference/system/log.rst b/docs/zh_CN/api-reference/system/log.rst index b2e313763e..ccfa490c39 100644 --- a/docs/zh_CN/api-reference/system/log.rst +++ b/docs/zh_CN/api-reference/system/log.rst @@ -135,3 +135,7 @@ API 参考 ------------- .. include-build-file:: inc/esp_log.inc +.. include-build-file:: inc/esp_log_level.inc +.. include-build-file:: inc/esp_log_buffer.inc +.. include-build-file:: inc/esp_log_timestamp.inc +.. include-build-file:: inc/esp_log_color.inc