Added the option to print system time rather than RTOS time in ESP_LOGx functions (IDFGH-1773)

components/log/Kconfig

@@ -44,5 +44,17 @@ menu "Log output"
 
             In order to view these, your terminal program must support ANSI color codes.
 
+    config LOG_SYSTEM_TIME
+        bool "Use system time in log output"
+        default "n"
+        help
+            Display the system time (HH:MM:SS.sss) in the log output rather than the 
+            RTOS time. Currently this will not get used in logging from binary blobs
+			(i.e WiFi & Bluetooth libraries), these will still print the RTOS tick time.
+
+            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.
+
 
 endmenu

components/log/include/esp_log.h

@@ -86,6 +86,21 @@ vprintf_like_t esp_log_set_vprintf(vprintf_like_t func);
  */
 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 WiFi & 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
  *
@@ -242,6 +257,7 @@ void esp_log_write(esp_log_level_t level, const char* tag, const char* format, .
 #endif //CONFIG_LOG_COLORS
 
 #define LOG_FORMAT(letter, format)  LOG_COLOR_ ## letter #letter " (%d) %s: " format LOG_RESET_COLOR "\n"
+#define LOG_SYSTEM_TIME_FORMAT(letter, format)  LOG_COLOR_ ## letter #letter " (%s) %s: " format LOG_RESET_COLOR "\n"
 
 /** @endcond */
 
@@ -295,13 +311,23 @@ void esp_log_write(esp_log_level_t level, const char* tag, const char* format, .
  *
  * @see ``printf``
  */
+#if CONFIG_LOG_SYSTEM_TIME
+#define ESP_LOG_LEVEL(level, tag, format, ...) do {                     \
+        if (level==ESP_LOG_ERROR )          { esp_log_write(ESP_LOG_ERROR,      tag, LOG_SYSTEM_TIME_FORMAT(E, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
+        else if (level==ESP_LOG_WARN )      { esp_log_write(ESP_LOG_WARN,       tag, LOG_SYSTEM_TIME_FORMAT(W, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
+        else if (level==ESP_LOG_DEBUG )     { esp_log_write(ESP_LOG_DEBUG,      tag, LOG_SYSTEM_TIME_FORMAT(D, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
+        else if (level==ESP_LOG_VERBOSE )   { esp_log_write(ESP_LOG_VERBOSE,    tag, LOG_SYSTEM_TIME_FORMAT(V, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
+        else                                { esp_log_write(ESP_LOG_INFO,       tag, LOG_SYSTEM_TIME_FORMAT(I, format), esp_log_system_timestamp(), tag, ##__VA_ARGS__); } \
+    } while(0)
+#else
 #define ESP_LOG_LEVEL(level, tag, format, ...) do {                     \
         if (level==ESP_LOG_ERROR )          { esp_log_write(ESP_LOG_ERROR,      tag, LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
         else if (level==ESP_LOG_WARN )      { esp_log_write(ESP_LOG_WARN,       tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
         else if (level==ESP_LOG_DEBUG )     { esp_log_write(ESP_LOG_DEBUG,      tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
         else if (level==ESP_LOG_VERBOSE )   { esp_log_write(ESP_LOG_VERBOSE,    tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
         else                                { esp_log_write(ESP_LOG_INFO,       tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \
     } while(0)
+#endif // CONFIG_LOG_SYSTEM_TIME
 
 /** runtime macro to output logs at a specified level. Also check the level with ``LOG_LOCAL_LEVEL``.
  *

components/log/log.c

@@ -53,6 +53,8 @@
 #include <stdio.h>
 #include <assert.h>
 #include <ctype.h>
+#include <time.h>
+#include <sys/time.h>
 
 #include "esp_log.h"
 
@@ -332,6 +334,52 @@ uint32_t ATTR esp_log_early_timestamp(void)
 
 #ifndef BOOTLOADER_BUILD
 
+char* IRAM_ATTR esp_log_system_timestamp(void)
+{
+    static char buffer[15] = {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); 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 tm timeinfo;
+        struct timespec tv;
+        time_t now;
+
+        time(&now);
+        localtime_r(&now, &timeinfo);
+        clock_gettime(CLOCK_REALTIME, &tv);
+        sprintf(buffer, 
+                "%02d:%02d:%02d.%03ld", 
+                timeinfo.tm_hour, 
+                timeinfo.tm_min, 
+                timeinfo.tm_sec, 
+                tv.tv_nsec / 1000000);
+
+        return buffer;
+    }
+}
+
 uint32_t IRAM_ATTR esp_log_timestamp(void)
 {
     if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) {