Merge branch 'feature/logv2' into 'master'

feat(log): Intermediate log refactoring

See merge request espressif/esp-idf!30683

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

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

components/bootloader/Kconfig.projbuild

@@ -38,34 +38,7 @@ menu "Bootloader config"
 
     endchoice
 
-    choice BOOTLOADER_LOG_LEVEL
+    orsource "Kconfig.log"
-        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
 
     menu "Serial Flash Configurations"
         config BOOTLOADER_SPI_CUSTOM_WP_PIN

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)
+if(NOT BOOTLOADER_BUILD)
-    list(APPEND srcs "log_noos.c")
+    list(APPEND priv_requires soc hal esp_hw_support)
-else()
-    list(APPEND srcs "src/os/log_write.c")
 
-    if(${target} STREQUAL "linux")
+    list(APPEND srcs "src/os/log_write.c")
-        list(APPEND srcs "log_linux.c")
-    else()
-        list(APPEND srcs "log_freertos.c")
-        list(APPEND priv_requires soc hal esp_hw_support)
-    endif()
 
     # Buffer APIs call ESP_LOG_LEVEL -> esp_log_write, which can not used in bootloader.
     list(APPEND srcs "src/buffer/log_buffers.c"

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

components/log/host_test/log_test/main/log_test.cpp

@@ -11,11 +11,25 @@
 #include <iostream>
 #include "esp_log.h"
 #include "esp_private/log_util.h"
+#include "esp_private/log_timestamp.h"
+#include "sdkconfig.h"
 
 #include <catch2/catch_test_macros.hpp>
 
 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\
+    const std::regex buffer_regex("I \\(" TIMESTAMP "\\) test: The way to get s.*\n\
-.*I \\([0-9]*\\) test: tarted is to qui.*\n\
+.*I \\(" TIMESTAMP "\\) test: tarted is to qui.*\n\
-.*I \\([0-9]*\\) test: t talking and be.*\n\
+.*I \\(" TIMESTAMP "\\) test: t talking and be.*\n\
-.*I \\([0-9]*\\) test: gin doing. - Wal.*\n\
+.*I \\(" TIMESTAMP "\\) test: gin doing. - Wal.*\n\
-.*I \\([0-9]*\\) test: t Disney", std::regex::ECMAScript);
+.*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);
+}

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

components/log/host_test/log_test/sdkconfig.ci.system_timestamp

@@ -0,0 +1 @@
+CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM=y

components/log/include/esp_log.h

@@ -9,11 +9,12 @@
 #include <stdint.h>
 #include <stdarg.h>
 #include <inttypes.h>
-#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"
 

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

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 <stdint.h>
+
+#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

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 <stdbool.h>
+#include <stdint.h>
+
+#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

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_timestamp:esp_log_timestamp (noflash)
-    log_freertos:esp_log_early_timestamp (noflash)
+    log_timestamp:esp_log_early_timestamp (noflash)
-    log_freertos:esp_log_impl_lock (noflash)
+    log_lock (noflash)
-    log_freertos:esp_log_impl_lock_timeout (noflash)
-    log_freertos:esp_log_impl_unlock (noflash)

components/log/log_freertos.c

@@ -1,121 +0,0 @@
-/*
- * SPDX-FileCopyrightText: 2015-2021 Espressif Systems (Shanghai) CO LTD
- *
- * SPDX-License-Identifier: Apache-2.0
- */
-
-#include <stdint.h>
-#include <time.h>
-#include <sys/time.h>
-#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
-}

components/log/src/linux/log_lock.c

@@ -5,9 +5,7 @@
  */
 
 #include <pthread.h>
-#include <time.h>
 #include <assert.h>
-#include <stdint.h>
 #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, &current_time);
-    assert(result == 0);
-    uint32_t milliseconds = current_time.tv_sec * 1000 + current_time.tv_nsec / 1000000;
-    return milliseconds;
-}

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 <assert.h>
+#include <time.h>
+#include "esp_log_timestamp.h"
+
+uint32_t esp_log_early_timestamp(void)
+{
+    struct timespec current_time;
+    int result = clock_gettime(CLOCK_MONOTONIC, &current_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")));

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 <assert.h>
+#include <time.h>
+#include <sys/time.h>
+#include "esp_log_timestamp.h"
+#include "esp_private/log_util.h"
+#include "esp_private/log_timestamp.h"
+#include "sdkconfig.h"
+
+#if !BOOTLOADER_BUILD
+#include <sys/lock.h>
+#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;
+}

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 <assert.h>
+#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;
+}

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 <assert.h>
-#include "esp_private/log_lock.h"
 #include "esp_rom_sys.h"
 #include "esp_cpu.h"
-
+#include "esp_log_timestamp.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;
-}
 
 /* FIXME: define an API for getting the timestamp in soc/hal IDF-2351 */
 uint32_t esp_log_early_timestamp(void)

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);
+}

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

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 \

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

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