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

components/log/CMakeLists.txt

@@ -1,19 +1,24 @@
 idf_build_get_property(target IDF_TARGET)
 
-set(srcs "")
-set(priv_requires "")
-
 if(BOOTLOADER_BUILD)
-    list(APPEND srcs "log_noos.c")
+    set(system_target "noos")
 else()
-    list(APPEND srcs "src/os/log_write.c")
-
     if(${target} STREQUAL "linux")
-        list(APPEND srcs "log_linux.c")
+        set(system_target "linux")
     else()
-        list(APPEND srcs "log_freertos.c")
-        list(APPEND priv_requires soc hal esp_hw_support)
+        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(NOT BOOTLOADER_BUILD)
+    list(APPEND priv_requires soc hal esp_hw_support)
+
+    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"

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,19 +233,19 @@ 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));
 }
 
 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);
+}

components/log/host_test/log_test/pytest_log_linux.py

@@ -8,6 +8,7 @@
 @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