log: Add menuconfig option to log system time rather than RTOS time

Merges https://github.com/espressif/esp-idf/pull/3958

components/log/Kconfig

@@ -44,5 +44,30 @@ menu "Log output"
 
             In order to view these, your terminal program must support ANSI color codes.
 
+    choice LOG_TIMESTAMP_SOURCE
+        prompt "Log Timestamps"
+        default LOG_TIMESTAMP_SOURCE_RTOS
+        help
+            Choose what sort of timestamp is displayed in the log output:
+
+            - Milliseconds since boot is calulated 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 ESP32's
+              RTC and FRC1 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)
+
+            - 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_RTOS
+            bool "Milliseconds Since Boot"
+        config LOG_TIMESTAMP_SOURCE_SYSTEM
+            bool "System Time"
+    endchoice
 
 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,6 +311,7 @@ void esp_log_write(esp_log_level_t level, const char* tag, const char* format, .
  *
  * @see ``printf``
  */
+#if CONFIG_LOG_TIMESTAMP_SOURCE_RTOS
 #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__); } \
@@ -302,6 +319,15 @@ void esp_log_write(esp_log_level_t level, const char* tag, const char* format, .
         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)
+#elif CONFIG_LOG_TIMESTAMP_SOURCE_SYSTEM
+#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)
+#endif //CONFIG_LOG_TIMESTAMP_SOURCE_xxx
 
 /** 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,46 @@ uint32_t ATTR esp_log_early_timestamp(void)
 
 #ifndef BOOTLOADER_BUILD
 
+char* IRAM_ATTR 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 IRAM_ATTR esp_log_timestamp(void)
 {
     if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) {