From 09fe8f70854ef7b6a45139118f88b405ca34b3c7 Mon Sep 17 00:00:00 2001
From: Wu Jian Gang <wujiangang@espressif.com>
Date: Fri, 28 Dec 2018 13:55:32 +0800
Subject: [PATCH] fix(log): Fix log time mismatch

When system startup, using 2*crystal as clock source.
---
 .../bootloader_support/src/bootloader_common.c      |  5 -----
 components/esp8266/Kconfig                          | 13 +++++++++++++
 components/esp8266/include/esp_system.h             | 10 ++++++++++
 components/esp8266/source/reset_reason.c            |  2 +-
 components/log/include/esp_log.h                    | 10 ++++++++++
 components/log/log.c                                | 13 ++++++++++---
 6 files changed, 44 insertions(+), 9 deletions(-)

diff --git a/components/bootloader_support/src/bootloader_common.c b/components/bootloader_support/src/bootloader_common.c
index 823af3f7..c82eeda8 100644
--- a/components/bootloader_support/src/bootloader_common.c
+++ b/components/bootloader_support/src/bootloader_common.c
@@ -178,11 +178,6 @@ bool bootloader_common_erase_part_type_data(const char *list_erase, bool ota_dat
 
 static const char *TAG = "bootloader_common";
 
-static inline uint32_t esp_log_early_timestamp()
-{
-    return xthal_get_ccount() / (80 * 1000);
-}
-
 uint32_t bootloader_common_ota_select_crc(const esp_ota_select_entry_t *s)
 {
     return crc32_le(UINT32_MAX, (uint8_t*)&s->ota_seq, 4);
diff --git a/components/esp8266/Kconfig b/components/esp8266/Kconfig
index de32e157..a48313d8 100644
--- a/components/esp8266/Kconfig
+++ b/components/esp8266/Kconfig
@@ -200,6 +200,19 @@ config ESP8266_CORE_GLOBAL_DATA_LINK_IRAM
     help
         Link libcore.a internal global data(.bss .data COMMON) from DRAM to IRAM.
 
+choice CRYSTAL_USED
+    prompt "Crystal used in your module or board"
+    default CRYSTAL_USED_26MHZ
+    help
+        For most modules, 26MHz is the default crystal. If you use special module,
+        you can reconfigure this option.
+
+config CRYSTAL_USED_26MHZ
+    bool "26MHz"
+config CRYSTAL_USED_40MHZ
+    bool "40MHz"
+endchoice
+
 endmenu
 
 menu WIFI
diff --git a/components/esp8266/include/esp_system.h b/components/esp8266/include/esp_system.h
index 986d1561..6c03be6a 100644
--- a/components/esp8266/include/esp_system.h
+++ b/components/esp8266/include/esp_system.h
@@ -19,10 +19,20 @@
 #include <stdbool.h>
 #include "esp_err.h"
 
+#include "sdkconfig.h"
+
 #ifdef __cplusplus
 extern "C" {
 #endif
 
+#if CONFIG_CRYSTAL_USED_26MHZ
+#define CRYSTAL_USED 26
+#endif
+
+#if CONFIG_CRYSTAL_USED_40MHZ
+#define CRYSTAL_USED 40
+#endif
+
 typedef enum {
     ESP_MAC_WIFI_STA,
     ESP_MAC_WIFI_SOFTAP,
diff --git a/components/esp8266/source/reset_reason.c b/components/esp8266/source/reset_reason.c
index 1cd2b8bf..ec337069 100644
--- a/components/esp8266/source/reset_reason.c
+++ b/components/esp8266/source/reset_reason.c
@@ -113,7 +113,7 @@ void esp_reset_reason_init(void)
         esp_reset_reason_clear_hint();
     }
 
-    ESP_EARLY_LOGI(TAG, "RTC reset %u wakeup %u store %u, reason is %u", hw_reset, hw_wakeup, hint, s_reset_reason);
+    ESP_LOGI(TAG, "RTC reset %u wakeup %u store %u, reason is %u", hw_reset, hw_wakeup, hint, s_reset_reason);
 }
 
 /**
diff --git a/components/log/include/esp_log.h b/components/log/include/esp_log.h
index 05283386..50fc3907 100644
--- a/components/log/include/esp_log.h
+++ b/components/log/include/esp_log.h
@@ -78,6 +78,16 @@ void esp_log_level_set(const char* tag, esp_log_level_t level);
  */
 putchar_like_t esp_log_set_putchar(putchar_like_t func);
 
+/**
+ * @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
  *
diff --git a/components/log/log.c b/components/log/log.c
index fc59a4c1..8f8cb3e9 100644
--- a/components/log/log.c
+++ b/components/log/log.c
@@ -27,6 +27,7 @@
 #include "xtensa/hal.h"
 
 #include "esp_log.h"
+#include "esp_system.h"
 
 #ifdef CONFIG_LOG_COLORS
 #define LOG_COLOR           "\033[0;%dm"
@@ -52,9 +53,9 @@ static const char s_log_prefix[ESP_LOG_MAX] = {
     'V', //  ESP_LOG_VERBOSE
 };
 
-static uint32_t IRAM_ATTR esp_log_early_timestamp()
+uint32_t IRAM_ATTR esp_log_early_timestamp()
 {
-    return xthal_get_ccount() / (80 * 1000);
+    return xthal_get_ccount() / ((CRYSTAL_USED * 2) * 1000);
 }
 
 #ifndef BOOTLOADER_BUILD
@@ -191,7 +192,13 @@ static int esp_log_write_str(const char *s)
 
 static uint32_t esp_log_timestamp()
 {
-    return clock() * (1000 / CLOCKS_PER_SEC) + esp_log_early_timestamp() % (1000 / CLOCKS_PER_SEC);
+    static uint32_t base = 0;
+
+    if (base == 0) {
+        base = esp_log_early_timestamp();
+    }
+
+    return base + clock() * (1000 / CLOCKS_PER_SEC);
 }
 #endif