feat(log): Adds new timestamp APIs and bootloader log Kconfigs

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,28 @@
+menu "Format"
+
+    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

@@ -10,7 +10,8 @@ else()
     endif()
 endif()
 
-set(srcs "src/${system_target}/log_timestamp.c")
+set(srcs "src/${system_target}/log_timestamp.c"
+         "src/log_timestamp_common.c")
 set(priv_requires "")
 
 if(BOOTLOADER_BUILD)

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_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/src/linux/log_timestamp.c

@@ -8,7 +8,7 @@
 #include <time.h>
 #include "esp_log_timestamp.h"
 
-uint32_t esp_log_timestamp(void)
+uint32_t esp_log_early_timestamp(void)
 {
     struct timespec current_time;
     int result = clock_gettime(CLOCK_MONOTONIC, &current_time);
@@ -16,3 +16,5 @@ uint32_t esp_log_timestamp(void)
     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/os/log_timestamp.c

@@ -4,64 +4,16 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
-#include <time.h>
-#include <sys/time.h>
 #include "freertos/FreeRTOS.h"
 #include "freertos/task.h"
 #include "esp_cpu.h" // for esp_cpu_get_cycle_count()
 #include "esp_compiler.h"
-#include "esp_private/log_util.h"
-#include "esp_private/log_lock.h"
 #include "esp_log_timestamp.h"
-
+#include "sdkconfig.h"
-static inline bool is_early_log(void)
-{
-    return xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED;
-}
-
-char *esp_log_system_timestamp(void)
-{
-    static char buffer[18] = {0};
-    static _lock_t bufferLock = 0;
-
-    if (is_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;
-            }
-        }
-        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(is_early_log())) {
+    if (unlikely(xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED)) {
         return esp_log_early_timestamp();
     }
     static uint32_t base = 0;