components/log: add implementation, update a few components to use it

This also removes logging implementation from bootloader and replaces it
with the one provided by the log component. Some occurrences of printf
and ets_printf have been changed to ESP_LOGx APIs.

components/bootloader/Kconfig.projbuild

@@ -1,33 +1,3 @@
 menu "Bootloader config"
 
-choice BOOTLOADER_LOG_LEVEL
-   bool "Bootloader log verbosity"
-   default BOOTLOADER_LOG_LEVEL_NOTICE
-   help
-       Specify how much output to see in the bootloader logs.
-
-       Note that if MTDO is HIGH on reset, all early boot output
-       (including bootloader logs) are suppressed.
-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_NOTICE
-   bool "Notice"
-config BOOTLOADER_LOG_LEVEL_DEBUG
-   bool "Debug"
-endchoice
-
-config BOOTLOADER_LOG_COLORS
-   bool "Use ANSI terminal colors in bootloader log output"
-   default "y"
-   help
-      Enable ANSI terminal color codes in bootloader output.
-
-      In order to view these, your terminal program must support ANSI color codes.
-
 endmenu

components/bootloader/src/Makefile

@@ -4,7 +4,7 @@
 #
 
 PROJECT_NAME := bootloader
-COMPONENTS := esptool_py bootloader
+COMPONENTS := esptool_py bootloader log
 
 # The bootloader pseudo-component is also included in this build, for its Kconfig.projbuild to be included.
 #
@@ -12,6 +12,6 @@ COMPONENTS := esptool_py bootloader
 IS_BOOTLOADER_BUILD := 1
 
 #We cannot include the esp32 component directly but we need its includes. This is fixed by
-#adding it in the main/Makefile directory.
+EXTRA_CFLAGS := -D BOOTLOADER_BUILD=1 -I $(IDF_PATH)/components/esp32/include 
 
 include $(IDF_PATH)/make/project.mk

components/bootloader/src/main/bootloader_log.h

@@ -1,114 +0,0 @@
-// Copyright 2015-2016 Espressif Systems (Shanghai) PTE LTD
-//
-// Licensed under the Apache License, Version 2.0 (the "License");
-// you may not use this file except in compliance with the License.
-// You may obtain a copy of the License at
-
-//     http://www.apache.org/licenses/LICENSE-2.0
-//
-// Unless required by applicable law or agreed to in writing, software
-// distributed under the License is distributed on an "AS IS" BASIS,
-// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
-// See the License for the specific language governing permissions and
-// limitations under the License.
-#ifndef __BOOT_LOG_H__
-#define __BOOT_LOG_H__
-
-#ifdef __cplusplus
-extern "C"
-{
-#endif
-
-#include "sdkconfig.h"
-
-#define BOOT_LOG_LEVEL_NONE       (0)
-#define BOOT_LOG_LEVEL_ERROR      (1)
-#define BOOT_LOG_LEVEL_WARN       (2)
-#define BOOT_LOG_LEVEL_INFO       (3)
-#define BOOT_LOG_LEVEL_NOTICE     (4)
-#define BOOT_LOG_LEVEL_DEBUG      (5)
-
-#define Black   "30"
-#define Red     "31"
-#define Green   "32"
-#define Brown   "33"
-#define Blue    "34"
-#define Purple  "35"
-#define Cyan    "36"
-
-#if CONFIG_BOOTLOADER_LOG_COLORS
-#define LOG_COLOR(COLOR) "\033[0;"COLOR"m"
-#define LOG_BOLD(COLOR)  "\033[1;"COLOR"m"
-#define LOG_RESET_COLOR "\033[0m"
-#else
-#define LOG_COLOR(...)
-#define LOG_BOLD(...)
-#define LOG_RESET_COLOR ""
-#endif
-
-// BOOT_LOG_LEVEL defined by make menuconfig
-#if CONFIG_BOOTLOADER_LOG_LEVEL_NONE
-#define BOOT_LOG_LEVEL BOOT_LOG_LEVEL_NONE
-#elif CONFIG_BOOTLOADER_LOG_LEVEL_ERROR
-#define BOOT_LOG_LEVEL BOOT_LOG_LEVEL_ERROR
-#elif CONFIG_BOOTLOADER_LOG_LEVEL_WARN
-#define BOOT_LOG_LEVEL BOOT_LOG_LEVEL_WARN
-#elif CONFIG_BOOTLOADER_LOG_LEVEL_INFO
-#define BOOT_LOG_LEVEL BOOT_LOG_LEVEL_INFO
-#elif CONFIG_BOOTLOADER_LOG_LEVEL_NOTICE
-#define BOOT_LOG_LEVEL BOOT_LOG_LEVEL_NOTICE
-#elif CONFIG_BOOTLOADER_LOG_LEVEL_DEBUG
-#define BOOT_LOG_LEVEL BOOT_LOG_LEVEL_DEBUG
-#else
-#error "No bootloader log level set in menuconfig!"
-#endif
-
-//printf("\033[0;36m[NOTICE][%s][%s][%d]\n" format "\r\n", __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__);
-#define log_notice(format, ...) \
-    do{\
-        if(BOOT_LOG_LEVEL >= BOOT_LOG_LEVEL_NOTICE){\
-            ets_printf(LOG_COLOR(Cyan) format "\r\n", ##__VA_ARGS__); \
-            ets_printf(LOG_RESET_COLOR); \
-        }\
-    }while(0)
-
-#define log_info(format, ...) \
-    do{\
-        if(BOOT_LOG_LEVEL >= BOOT_LOG_LEVEL_INFO){\
-            ets_printf(LOG_BOLD(Cyan) format "\r\n", ##__VA_ARGS__); \
-            ets_printf(LOG_RESET_COLOR); \
-        }\
-    }while(0)
-
-//printf("\033[0;31m[ERROR][%s][%s][%d]\n" format "\r\n", __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__);
-#define log_error(format, ...) \
-    do{\
-        if(BOOT_LOG_LEVEL >= BOOT_LOG_LEVEL_ERROR){\
-            ets_printf(LOG_COLOR(Red) "[ERROR][%s][%s][%d]\n" format "\r\n", __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__); \
-            ets_printf(LOG_RESET_COLOR); \
-        }\
-    }while(0)
-
-//printf("\033[1;33m[WARN][%s][%s][%d]\n" format "\r\n", __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__);
-#define log_warn(format, ...) \
-    do{\
-        if(BOOT_LOG_LEVEL >= BOOT_LOG_LEVEL_WARN){\
-            ets_printf(LOG_BOLD(Brown) "[WARN][%s][%s][%d]\n" format "\r\n", __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__); \
-            ets_printf(LOG_RESET_COLOR); \
-        }\
-    }while(0)
-
-//printf("\033[1;32m[DEBUG][%s][%s][%d]\n" format "\r\n", __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__);
-#define log_debug(format, ...) \
-    do{\
-        if(BOOT_LOG_LEVEL >= BOOT_LOG_LEVEL_DEBUG){\
-            ets_printf(LOG_BOLD(Green) "[DEBUG][%s][%s][%d]\n" format "\r\n", __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__); \
-            ets_printf(LOG_RESET_COLOR); \
-        }\
-    }while(0)
-
-#ifdef __cplusplus
-}
-#endif
-
-#endif /* __BOOT_LOGGING_H__ */

components/bootloader/src/main/bootloader_start.c

@@ -16,6 +16,7 @@
 #include <limits.h>
 
 #include "esp_attr.h"
+#include "esp_log.h"
 
 #include "rom/cache.h"
 #include "rom/ets_sys.h"
@@ -31,11 +32,12 @@
 
 #include "sdkconfig.h"
 
-#include "bootloader_log.h"
 #include "bootloader_config.h"
 
 extern int _bss_start;
 extern int _bss_end;
+
+static const char* TAG = "boot";
 /*
 We arrive here after the bootloader finished loading the program from flash. The hardware is mostly uninitialized,
 flash cache is down and the app CPU is in reset. We do have a stack, so we can do the initialization in C.
@@ -130,7 +132,7 @@ uint32_t get_bin_len(uint32_t pos)
 {   
     uint32_t len = 8 + 16;
     uint8_t i;
-    log_debug("pos %d %x\n",pos,*(uint8_t *)pos);
+    ESP_LOGD(TAG, "pos %d %x",pos,*(uint8_t *)pos);
     if(0xE9 != *(uint8_t *)pos) {
         return 0;
     }
@@ -142,7 +144,7 @@ uint32_t get_bin_len(uint32_t pos)
     } else {
         len += 16;
     }
-    log_debug("bin length = %d\n", len);
+    ESP_LOGD(TAG, "bin length = %d", len);
     return len;
 }
 
@@ -161,7 +163,7 @@ void boot_cache_redirect( uint32_t pos, size_t size )
     uint32_t count = (size + 0xffff) / 0x10000;
     Cache_Read_Disable( 0 );
     Cache_Flush( 0 );
-    log_debug( "mmu set paddr=%08x count=%d", pos_aligned, count );
+    ESP_LOGD(TAG, "mmu set paddr=%08x count=%d", pos_aligned, count );
     cache_flash_mmu_set( 0, 0, 0x3f400000, pos_aligned, 64, count );
     Cache_Read_Enable( 0 );
 }
@@ -183,13 +185,13 @@ bool load_partition_table(bootloader_state_t* bs, uint32_t addr)
     int index = 0;
     char *partition_usage;
 
-    log_info("Partition Table:");
-    log_info("## Label            Usage          Type ST Offset   Length");
+    ESP_LOGI(TAG, "Partition Table:");
+    ESP_LOGI(TAG, "## Label            Usage          Type ST Offset   Length");
 
     while (addr < end) {
-        log_debug("load partition table entry from %x(%08x)", addr, MEM_CACHE(addr));
+        ESP_LOGD(TAG, "load partition table entry from %x(%08x)", addr, MEM_CACHE(addr));
         memcpy(&partition, MEM_CACHE(addr), sizeof(partition));
-        log_debug("type=%x subtype=%x", partition.type, partition.subtype);
+        ESP_LOGD(TAG, "type=%x subtype=%x", partition.type, partition.subtype);
         partition_usage = "unknown";
 
         if (partition.magic == PARTITION_MAGIC) { /* valid partition definition */
@@ -244,14 +246,14 @@ bool load_partition_table(bootloader_state_t* bs, uint32_t addr)
         }
 
         /* print partition type info */
-        log_info("%2d %-16s %-16s %02x %02x %08x %08x", index, partition.label, partition_usage,
+        ESP_LOGI(TAG, "%2d %-16s %-16s %02x %02x %08x %08x", index, partition.label, partition_usage,
                  partition.type, partition.subtype,
                  partition.pos.offset, partition.pos.size);
         index++;
         addr += sizeof(partition);
     }
 
-    log_info("End of partition table");
+    ESP_LOGI(TAG,"End of partition table");
     return true;
 }
 
@@ -274,14 +276,7 @@ static bool ota_select_valid(const ota_select *s)
 
 void bootloader_main()
 {
-    //Run start routine.
-    /*ESP32 2ND bootload start here*/
-    log_info( "\n" );
-    log_info( "**************************************" );
-    log_info( "*       hello espressif ESP32!       *" );
-    log_info( "*        2nd boot is running!        *" );
-    log_info( "*            version (%s)          *", BOOT_VERSION);
-    log_info( "**************************************");
+    ESP_LOGI(TAG, "Espressif ESP32 2nd stage bootloader v. %s", BOOT_VERSION);
 
     struct flash_hdr    fhdr;
     bootloader_state_t bs;
@@ -289,7 +284,7 @@ void bootloader_main()
     ota_select sa,sb;
     memset(&bs, 0, sizeof(bs));
 
-    log_notice( "compile time %s\n", __TIME__ );
+    ESP_LOGI(TAG, "compile time " __TIME__ );
     /* close watch dog here */
     REG_CLR_BIT( RTC_WDTCONFIG0, RTC_CNTL_WDT_FLASHBOOT_MOD_EN );
     REG_CLR_BIT( WDTCONFIG0(0), TIMERS_WDT_FLASHBOOT_MOD_EN );
@@ -302,14 +297,14 @@ void bootloader_main()
     print_flash_info(&fhdr);
 
     if (!load_partition_table(&bs, PARTITION_ADD)) {
-        log_error("load partition table error!");
+        ESP_LOGE(TAG, "load partition table error!");
         return;
     }
 
     partition_pos_t load_part_pos;
 
     if (bs.ota_info.offset != 0) {              // check if partition table has OTA info partition
-        //log_error("OTA info sector handling is not implemented");
+        //ESP_LOGE("OTA info sector handling is not implemented");
         boot_cache_redirect(bs.ota_info.offset, bs.ota_info.size );
         memcpy(&sa,MEM_CACHE(bs.ota_info.offset & 0x0000ffff),sizeof(sa));
         memcpy(&sb,MEM_CACHE((bs.ota_info.offset + 0x1000)&0x0000ffff) ,sizeof(sb));
@@ -325,13 +320,13 @@ void bootloader_main()
             spiRet1 = SPIEraseSector(bs.ota_info.offset/0x1000);       
             spiRet2 = SPIEraseSector(bs.ota_info.offset/0x1000+1);       
             if (spiRet1 != SPI_FLASH_RESULT_OK || spiRet2 != SPI_FLASH_RESULT_OK ) {  
-                log_error(SPI_ERROR_LOG);
+                ESP_LOGE(TAG, SPI_ERROR_LOG);
                 return;
             } 
             spiRet1 = SPIWrite(bs.ota_info.offset,(uint32_t *)&sa,sizeof(ota_select));
             spiRet2 = SPIWrite(bs.ota_info.offset + 0x1000,(uint32_t *)&sb,sizeof(ota_select));
             if (spiRet1 != SPI_FLASH_RESULT_OK || spiRet2 != SPI_FLASH_RESULT_OK ) {  
-                log_error(SPI_ERROR_LOG);
+                ESP_LOGE(TAG, SPI_ERROR_LOG);
                 return;
             } 
             Cache_Read_Enable(0);  
@@ -344,7 +339,7 @@ void bootloader_main()
             }else if(ota_select_valid(&sb)) {
                 load_part_pos = bs.ota[(sb.ota_seq - 1) % bs.app_count];
             }else {
-                log_error("ota data partition info error");
+                ESP_LOGE(TAG, "ota data partition info error");
                 return;
             }
         }
@@ -353,15 +348,15 @@ void bootloader_main()
     } else if (bs.test.offset != 0) {           // otherwise, look for test app parition
         load_part_pos = bs.test;
     } else {                                    // nothing to load, bail out
-        log_error("nothing to load");
+        ESP_LOGE(TAG, "nothing to load");
         return;
     }
 
-    log_info("Loading app partition at offset %08x", load_part_pos);
+    ESP_LOGI(TAG, "Loading app partition at offset %08x", load_part_pos);
     if(fhdr.secury_boot_flag == 0x01) {
         /* protect the 2nd_boot  */    
         if(false == secure_boot()){
-            log_error("secure boot failed");
+            ESP_LOGE(TAG, "secure boot failed");
             return;
         }
     }
@@ -369,7 +364,7 @@ void bootloader_main()
     if(fhdr.encrypt_flag == 0x01) {
         /* encrypt flash */            
         if (false == flash_encrypt(&bs)) {
-           log_error("flash encrypt failed");
+           ESP_LOGE(TAG, "flash encrypt failed");
            return;
         }
     }
@@ -395,7 +390,7 @@ void unpack_load_app(const partition_pos_t* partition)
     uint32_t irom_load_addr = 0;
     uint32_t irom_size = 0;
 
-    log_debug("bin_header: %u %u %u %u %08x\n", image_header.magic,
+    ESP_LOGD(TAG, "bin_header: %u %u %u %u %08x", image_header.magic,
               image_header.blocks,
               image_header.spi_mode,
               image_header.spi_size,
@@ -420,7 +415,7 @@ void unpack_load_app(const partition_pos_t* partition)
         }
 
         if (address >= DROM_LOW && address < DROM_HIGH) {
-            log_debug("found drom section, map from %08x to %08x\n", pos,
+            ESP_LOGD(TAG, "found drom section, map from %08x to %08x", pos,
                       section_header.load_addr);
             drom_addr = partition->offset + pos - sizeof(section_header);
             drom_load_addr = section_header.load_addr;
@@ -430,7 +425,7 @@ void unpack_load_app(const partition_pos_t* partition)
         }
 
         if (address >= IROM_LOW && address < IROM_HIGH) {
-            log_debug("found irom section, map from %08x to %08x\n", pos,
+            ESP_LOGD(TAG, "found irom section, map from %08x to %08x", pos,
                       section_header.load_addr);
             irom_addr = partition->offset + pos - sizeof(section_header);
             irom_load_addr = section_header.load_addr;
@@ -439,7 +434,7 @@ void unpack_load_app(const partition_pos_t* partition)
             map = true;
         }
 
-        log_notice("section %d: paddr=0x%08x vaddr=0x%08x size=0x%05x (%6d) %s", section_index, pos, section_header.load_addr, section_header.data_len, section_header.data_len, (load)?"load":(map)?"map":"");
+        ESP_LOGI(TAG, "section %d: paddr=0x%08x vaddr=0x%08x size=0x%05x (%6d) %s", section_index, pos, section_header.load_addr, section_header.data_len, section_header.data_len, (load)?"load":(map)?"map":"");
 
         if (!load) {
             pos += section_header.data_len;
@@ -468,29 +463,29 @@ void IRAM_ATTR set_cache_and_start_app(
     uint32_t irom_size, 
     uint32_t entry_addr)
 {
-    log_debug("configure drom and irom and start\n");
+    ESP_LOGD(TAG, "configure drom and irom and start");
     Cache_Read_Disable( 0 );
     Cache_Read_Disable( 1 );
     Cache_Flush( 0 );
     Cache_Flush( 1 );
     uint32_t drom_page_count = (drom_size + 64*1024 - 1) / (64*1024); // round up to 64k
-    log_debug( "d mmu set paddr=%08x vaddr=%08x size=%d n=%d \n", drom_addr & 0xffff0000, drom_load_addr & 0xffff0000, drom_size, drom_page_count );
+    ESP_LOGV(TAG, "d mmu set paddr=%08x vaddr=%08x size=%d n=%d", drom_addr & 0xffff0000, drom_load_addr & 0xffff0000, drom_size, drom_page_count );
     int rc = cache_flash_mmu_set( 0, 0, drom_load_addr & 0xffff0000, drom_addr & 0xffff0000, 64, drom_page_count );
-    log_debug( "rc=%d", rc );
+    ESP_LOGV(TAG, "rc=%d", rc );
     rc = cache_flash_mmu_set( 1, 0, drom_load_addr & 0xffff0000, drom_addr & 0xffff0000, 64, drom_page_count );
-    log_debug( "rc=%d", rc );
+    ESP_LOGV(TAG, "rc=%d", rc );
     uint32_t irom_page_count = (irom_size + 64*1024 - 1) / (64*1024); // round up to 64k
-    log_debug( "i mmu set paddr=%08x vaddr=%08x size=%d n=%d\n", irom_addr & 0xffff0000, irom_load_addr & 0xffff0000, irom_size, irom_page_count );
+    ESP_LOGV(TAG, "i mmu set paddr=%08x vaddr=%08x size=%d n=%d", irom_addr & 0xffff0000, irom_load_addr & 0xffff0000, irom_size, irom_page_count );
     rc = cache_flash_mmu_set( 0, 0, irom_load_addr & 0xffff0000, irom_addr & 0xffff0000, 64, irom_page_count );
-    log_debug( "rc=%d", rc );
+    ESP_LOGV(TAG, "rc=%d", rc );
     rc = cache_flash_mmu_set( 1, 0, irom_load_addr & 0xffff0000, irom_addr & 0xffff0000, 64, irom_page_count );
-    log_debug( "rc=%d", rc );
+    ESP_LOGV(TAG, "rc=%d", rc );
     REG_CLR_BIT( PRO_CACHE_CTRL1_REG, (DPORT_PRO_CACHE_MASK_IRAM0) | (DPORT_PRO_CACHE_MASK_IRAM1 & 0) | (DPORT_PRO_CACHE_MASK_IROM0 & 0) | DPORT_PRO_CACHE_MASK_DROM0 | DPORT_PRO_CACHE_MASK_DRAM1 );
     REG_CLR_BIT( APP_CACHE_CTRL1_REG, (DPORT_APP_CACHE_MASK_IRAM0) | (DPORT_APP_CACHE_MASK_IRAM1 & 0) | (DPORT_APP_CACHE_MASK_IROM0 & 0) | DPORT_APP_CACHE_MASK_DROM0 | DPORT_APP_CACHE_MASK_DRAM1 );
     Cache_Read_Enable( 0 );
     Cache_Read_Enable( 1 );
 
-    log_notice("start: 0x%08x\n", entry_addr);
+    ESP_LOGD(TAG, "start: 0x%08x", entry_addr);
     typedef void (*entry_t)(void);
     entry_t entry = ((entry_t) entry_addr);
 
@@ -506,11 +501,11 @@ void print_flash_info(struct flash_hdr* pfhdr)
 
     struct flash_hdr fhdr = *pfhdr;
 
-    log_debug( "[D]: magic %02x\n", fhdr.magic );
-    log_debug( "[D]: blocks %02x\n", fhdr.blocks );
-    log_debug( "[D]: spi_mode %02x\n", fhdr.spi_mode );
-    log_debug( "[D]: spi_speed %02x\n", fhdr.spi_speed );
-    log_debug( "[D]: spi_size %02x\n", fhdr.spi_size );
+    ESP_LOGD(TAG, "magic %02x", fhdr.magic );
+    ESP_LOGD(TAG, "blocks %02x", fhdr.blocks );
+    ESP_LOGD(TAG, "spi_mode %02x", fhdr.spi_mode );
+    ESP_LOGD(TAG, "spi_speed %02x", fhdr.spi_speed );
+    ESP_LOGD(TAG, "spi_size %02x", fhdr.spi_size );
 
     const char* str;
     switch ( fhdr.spi_speed ) {
@@ -534,7 +529,7 @@ void print_flash_info(struct flash_hdr* pfhdr)
         str = "20MHz";
         break;
     }
-    log_notice( "  SPI Speed      : %s", str );
+    ESP_LOGI(TAG, "SPI Speed      : %s", str );
 
     
 
@@ -566,7 +561,7 @@ void print_flash_info(struct flash_hdr* pfhdr)
         str = "DIO";
         break;
     }
-    log_notice( "  SPI Mode       : %s", str );
+    ESP_LOGI(TAG, "SPI Mode       : %s", str );
 
     
 
@@ -595,6 +590,6 @@ void print_flash_info(struct flash_hdr* pfhdr)
         str = "1MB";
         break;
     }
-    log_notice( "  SPI Flash Size : %s", str );
+    ESP_LOGI(TAG, "SPI Flash Size : %s", str );
 #endif
 }

components/bootloader/src/main/component.mk

@@ -8,6 +8,5 @@
 #
 
 COMPONENT_ADD_LDFLAGS := -L $(abspath .) -lmain -T esp32.bootloader.ld -T $(IDF_PATH)/components/esp32/ld/esp32.rom.ld 
-COMPONENT_EXTRA_INCLUDES := $(IDF_PATH)/components/esp32/include 
 
 include $(IDF_PATH)/make/component_common.mk

components/bootloader/src/main/flash_encrypt.c

@@ -16,6 +16,7 @@
 
 #include "esp_types.h"
 #include "esp_attr.h"
+#include "esp_log.h"
 
 #include "rom/cache.h"
 #include "rom/ets_sys.h"
@@ -28,13 +29,14 @@
 
 #include "sdkconfig.h"
 
-#include "bootloader_log.h"
 #include "bootloader_config.h"
 
+static const char* TAG = "flash_encrypt";
+
 /**
  *  @function :     bitcount
- *  @description:   caculate bit 1 in flash_crypt_cnt 
- *                  if it's even number ,need encrypt flash data,and burn efuse 
+ *  @description:   calculate bit 1 in flash_crypt_cnt
+ *                  if it's even number, need encrypt flash data, and burn efuse
  *
  *  @inputs:        n     flash_crypt_cnt               
  *  @return:        number of 1 in flash_crypt_cnt
@@ -68,19 +70,19 @@ bool flash_encrypt_write(uint32_t pos, uint32_t len)
        spiRet = SPIRead(pos, buf, SPI_SEC_SIZE);     
        if (spiRet != SPI_FLASH_RESULT_OK) {   
            Cache_Read_Enable(0); 
-           log_error(SPI_ERROR_LOG);
+           ESP_LOGE(TAG, SPI_ERROR_LOG);
            return false;    
        }    
        spiRet = SPIEraseSector(pos/SPI_SEC_SIZE);    
        if (spiRet != SPI_FLASH_RESULT_OK) { 
            Cache_Read_Enable(0);
-           log_error(SPI_ERROR_LOG);
+           ESP_LOGE(TAG, SPI_ERROR_LOG);
            return false;      
        }
        spiRet = SPI_Encrypt_Write(pos, buf, SPI_SEC_SIZE);
        if (spiRet != SPI_FLASH_RESULT_OK) {    
            Cache_Read_Enable(0); 
-           log_error(SPI_ERROR_LOG);
+           ESP_LOGE(TAG, SPI_ERROR_LOG);
            return false;       
        }   
        pos += SPI_SEC_SIZE;
@@ -104,53 +106,53 @@ bool flash_encrypt(bootloader_state_t *bs)
    uint32_t flash_crypt_cnt = REG_GET_FIELD(EFUSE_BLK0_RDATA0, EFUSE_FLASH_CRYPT_CNT);
    uint8_t count = bitcount(flash_crypt_cnt);
    int i = 0;
-   log_debug("flash crypt cnt %x, count %d\n", flash_crypt_cnt, count); 
+   ESP_LOGD(TAG, "flash encrypt cnt %x, bitcount %d\n", flash_crypt_cnt, count);
 
    if ((count % 2) == 0) {    
        boot_cache_redirect( 0, 64*1024);
         /* encrypt iv and abstruct */ 
-       if (false == flash_encrypt_write(0,SPI_SEC_SIZE)) {
-           log_error("encrypt iv and abstruct error"); 
+       if (false == flash_encrypt_write(0, SPI_SEC_SIZE)) {
+           ESP_LOGE(TAG, "encrypt iv and abstract error");
            return false;
        }
 
         /* encrypt write boot bin*/
        bin_len = get_bin_len((uint32_t)MEM_CACHE(0x1000));
        if(bin_len != 0) {
-           if (false == flash_encrypt_write(0x1000,bin_len)) {
-               log_error("encrypt 2nd boot error"); 
+           if (false == flash_encrypt_write(0x1000, bin_len)) {
+               ESP_LOGE(TAG, "encrypt 2nd boot error");
                return false;
            }
        } else {
-           log_error("2nd boot len error"); 
+           ESP_LOGE(TAG, "2nd boot len error");
            return false;
        }
         /* encrypt partition table */
-       if (false ==  flash_encrypt_write(PARTITION_ADD,SPI_SEC_SIZE)) {
-           log_error("encrypt partition table error"); 
+       if (false ==  flash_encrypt_write(PARTITION_ADD, SPI_SEC_SIZE)) {
+           ESP_LOGE(TAG, "encrypt partition table error");
            return false;
        }
 
         /* encrypt write factory bin  */
        if(bs->factory.offset != 0x00) {
-           log_debug("have factory bin\n");
-           boot_cache_redirect(bs->factory.offset,bs->factory.size);
+           ESP_LOGD(TAG, "have factory bin\n");
+           boot_cache_redirect(bs->factory.offset, bs->factory.size);
            bin_len = get_bin_len((uint32_t)MEM_CACHE(bs->factory.offset&0xffff));
            if(bin_len != 0) {           
-               if (false ==  flash_encrypt_write(bs->factory.offset,bin_len)) {
-                   log_error("encrypt factory bin error"); 
+               if (false ==  flash_encrypt_write(bs->factory.offset, bin_len)) {
+                   ESP_LOGE(TAG, "encrypt factory bin error");
                    return false;
                }
            }
        }
         /* encrypt write test bin  */
        if(bs->test.offset != 0x00) {
-           ets_printf("have test bin\n");
-           boot_cache_redirect(bs->test.offset,bs->test.size);
+           ESP_LOGD(TAG, "have test bin\n");
+           boot_cache_redirect(bs->test.offset, bs->test.size);
            bin_len = get_bin_len((uint32_t)MEM_CACHE(bs->test.offset&0xffff));
            if(bin_len != 0) {
-               if (false ==  flash_encrypt_write(bs->test.offset,bin_len)) {
-                   log_error("encrypt test bin error"); 
+               if (false ==  flash_encrypt_write(bs->test.offset, bin_len)) {
+                   ESP_LOGE(TAG, "encrypt test bin error");
                    return false;
                }
            }
@@ -158,33 +160,33 @@ bool flash_encrypt(bootloader_state_t *bs)
         /* encrypt write ota bin  */
        for (i = 0;i<16;i++) {
            if(bs->ota[i].offset != 0x00) {
-               log_debug("have ota[%d] bin\n",i);
-               boot_cache_redirect(bs->ota[i].offset,bs->ota[i].size);
+               ESP_LOGD(TAG, "have ota[%d] bin\n",i);
+               boot_cache_redirect(bs->ota[i].offset, bs->ota[i].size);
                bin_len = get_bin_len((uint32_t)MEM_CACHE(bs->ota[i].offset&0xffff));
                if(bin_len != 0) {    
-                   if (false == flash_encrypt_write(bs->ota[i].offset,bin_len)) {
-                       log_error("encrypt ota bin error"); 
+                   if (false == flash_encrypt_write(bs->ota[i].offset, bin_len)) {
+                       ESP_LOGE(TAG, "encrypt ota bin error");
                        return false;
                    }
                }
            }
        }
         /* encrypt write ota info bin  */
-       if (false == flash_encrypt_write(bs->ota_info.offset,2*SPI_SEC_SIZE)) {
-           log_error("encrypt ota binfo error"); 
+       if (false == flash_encrypt_write(bs->ota_info.offset, 2*SPI_SEC_SIZE)) {
+           ESP_LOGE(TAG, "encrypt ota info error");
            return false;
        }  
        REG_SET_FIELD(EFUSE_BLK0_WDATA0, EFUSE_FLASH_CRYPT_CNT, 0x04);   
        REG_WRITE(EFUSE_CONF, 0x5A5A);  /* efuse_pgm_op_ena, force no rd/wr disable */     
        REG_WRITE(EFUSE_CMD,  0x02);    /* efuse_pgm_cmd */     
        while (REG_READ(EFUSE_CMD));    /* wait for efuse_pagm_cmd=0 */
-       log_warn("burn  flash_crypt_cnt\n");   
+       ESP_LOGW(TAG, "burn  flash_crypt_cnt");
        REG_WRITE(EFUSE_CONF, 0x5AA5);  /* efuse_read_op_ena, release force */   
        REG_WRITE(EFUSE_CMD,  0x01);    /* efuse_read_cmd */     
        while (REG_READ(EFUSE_CMD));    /* wait for efuse_read_cmd=0 */  
        return true;
    } else {   
-       log_info("flash already encrypted.\n"); 
+       ESP_LOGI(TAG, "flash already encrypted.");
        return true;
    }
 }

components/bootloader/src/main/secure_boot.c

@@ -16,6 +16,7 @@
 
 #include "esp_attr.h"
 #include "esp_types.h"
+#include "esp_log.h"
 
 #include "rom/cache.h"
 #include "rom/ets_sys.h"
@@ -29,12 +30,13 @@
 
 #include "sdkconfig.h"
 
-#include "bootloader_log.h"
 #include "bootloader_config.h"
 
+static const char* TAG = "secure_boot";
+
 /**
  *  @function :     secure_boot_generate
- *  @description:   generate boot abstruct & iv 
+ *  @description:   generate boot abstract & iv
  *
  *  @inputs:        bool
  */
@@ -53,17 +55,17 @@ bool secure_boot_generate(uint32_t bin_len){
 	spiRet = SPIEraseSector(0);
 	if (spiRet != SPI_FLASH_RESULT_OK)
 	{   
-		log_error(SPI_ERROR_LOG);
+		ESP_LOGE(TAG, SPI_ERROR_LOG);
 		return false;
 	}
 	/* write iv to flash, 0x0000, 128 bytes (1024 bits) */
 	spiRet = SPIWrite(0, buf, 128);
 	if (spiRet != SPI_FLASH_RESULT_OK) 
 	{
-		log_error(SPI_ERROR_LOG);
+		ESP_LOGE(TAG, SPI_ERROR_LOG);
 		return false;
 	}
-	log_debug("write iv to flash.\n");
+	ESP_LOGD(TAG, "write iv to flash.");
 	Cache_Read_Enable(0);
 	/* read 4K code image from flash, for test */
 	for (i = 0; i < bin_len; i+=128) {
@@ -77,10 +79,10 @@ bool secure_boot_generate(uint32_t bin_len){
 	/* write abstract to flash, 0x0080, 64 bytes (512 bits) */
 	spiRet = SPIWrite(0x80, buf, 64);
 	if (spiRet != SPI_FLASH_RESULT_OK) {
-		log_error(SPI_ERROR_LOG);
+		ESP_LOGE(TAG, SPI_ERROR_LOG);
 		return false;
 	}
-	log_debug("write abstract to flash.\n");
+	ESP_LOGD(TAG, "write abstract to flash.");
 	Cache_Read_Enable(0);
 	return true;
 }
@@ -88,7 +90,7 @@ bool secure_boot_generate(uint32_t bin_len){
 
 /**
  *  @function :     secure_boot
- *  @description:   protect boot code inflash
+ *  @description:   protect boot code in flash
  *
  *  @inputs:        bool
  */
@@ -96,17 +98,17 @@ bool secure_boot(void){
 	uint32_t bin_len = 0;
 	if (REG_READ(EFUSE_BLK0_RDATA6) & EFUSE_RD_ABS_DONE_0)
 	{     
-		log_info("already secure boot !\n"); 
+		ESP_LOGD(TAG, "already secure boot !");
 		return true;
 	} else {  
 		boot_cache_redirect( 0, 64*1024);
 		bin_len = get_bin_len((uint32_t)MEM_CACHE(0x1000));
 		if (bin_len == 0) {
-			log_error("boot len is error");
+			ESP_LOGE(TAG, "boot len is error");
 			return false;
 		}
 		if (false == secure_boot_generate(bin_len)){
-			log_error("secure boot generate failed");
+			ESP_LOGE(TAG, "secure boot generate failed");
 			return false;
 		}  
 	}  
@@ -115,11 +117,11 @@ bool secure_boot(void){
 	REG_WRITE(EFUSE_CONF, 0x5A5A);  /* efuse_pgm_op_ena, force no rd/wr disable */     
 	REG_WRITE(EFUSE_CMD,  0x02);    /* efuse_pgm_cmd */    
 	while (REG_READ(EFUSE_CMD));    /* wait for efuse_pagm_cmd=0 */   
-	log_warn("burn abstract_done_0\n");   
+	ESP_LOGI(TAG, "burn abstract_done_0");
 	REG_WRITE(EFUSE_CONF, 0x5AA5);  /* efuse_read_op_ena, release force */   
 	REG_WRITE(EFUSE_CMD,  0x01);    /* efuse_read_cmd */     
 	while (REG_READ(EFUSE_CMD));    /* wait for efuse_read_cmd=0 */       
-	log_debug("read EFUSE_BLK0_RDATA6 %x\n", REG_READ(EFUSE_BLK0_RDATA6)); 
+	ESP_LOGD(TAG, "read EFUSE_BLK0_RDATA6 %x\n", REG_READ(EFUSE_BLK0_RDATA6));
 	return true;
 
 }

components/esp32/cpu_start.c

@@ -39,11 +39,11 @@
 #include "esp_event.h"
 #include "esp_spi_flash.h"
 #include "esp_ipc.h"
+#include "esp_log.h"
 
 static void IRAM_ATTR user_start_cpu0(void);
 static void IRAM_ATTR call_user_start_cpu1();
 static void IRAM_ATTR user_start_cpu1(void);
-void Cache_Read_Enable();
 extern void ets_setup_syscalls(void);
 
 
@@ -57,6 +57,8 @@ extern int _iram_romjumptable_end;
 extern int _iram_text_start;
 extern int _iram_text_end;
 
+static const char* TAG = "cpu_start";
+
 /*
 We arrive here after the bootloader finished loading the program from flash. The hardware is mostly uninitialized,
 flash cache is down and the app CPU is in reset. We do have a stack, so we can do the initialization in C.
@@ -110,13 +112,13 @@ void IRAM_ATTR call_user_start_cpu0() {
 
 	memset(&_bss_start, 0, (&_bss_end - &_bss_start) * sizeof(_bss_start));
 
-	//Initialize heap allocator
+	// Initialize heap allocator
 	heap_alloc_caps_init();
 
-	ets_printf("Pro cpu up.\n");
+	ESP_EARLY_LOGI(TAG, "Pro cpu up.");
     
 #ifndef CONFIG_FREERTOS_UNICORE
-	ets_printf("Starting app cpu, entry point is %p\n", call_user_start_cpu1);
+	ESP_EARLY_LOGI(TAG, "Starting app cpu, entry point is %p", call_user_start_cpu1);
 
 	SET_PERI_REG_MASK(APPCPU_CTRL_REG_B, DPORT_APPCPU_CLKGATE_EN);
 	CLEAR_PERI_REG_MASK(APPCPU_CTRL_REG_C, DPORT_APPCPU_RUNSTALL);
@@ -128,9 +130,10 @@ void IRAM_ATTR call_user_start_cpu0() {
 		ets_delay_us(100);
 	}
 #else
+	ESP_EARLY_LOGI(TAG, "Single core mode");
 	CLEAR_PERI_REG_MASK(APPCPU_CTRL_REG_B, DPORT_APPCPU_CLKGATE_EN);
 #endif
-	ets_printf("Pro cpu start user code\n");
+	ESP_EARLY_LOGI(TAG, "Pro cpu start user code");
 	user_start_cpu0();
 }
 
@@ -173,7 +176,7 @@ void IRAM_ATTR call_user_start_cpu1() {
 		"isync\n" \
 		:::"a4","a5");
 	
-	ets_printf("App cpu up.\n");
+	ESP_EARLY_LOGI(TAG, "App cpu up.");
 	app_cpu_started = 1;
 	user_start_cpu1();
 }
@@ -185,7 +188,7 @@ void IRAM_ATTR user_start_cpu1(void) {
 	while (port_xSchedulerRunning[0] == 0) {
 	    ;
 	}
-	ets_printf("Starting scheduler on APP CPU.\n");
+	ESP_LOGI(TAG, "Starting scheduler on APP CPU.");
 	xPortStartScheduler();
 }
 
@@ -201,7 +204,7 @@ static void do_global_ctors(void) {
 extern esp_err_t app_main(void *ctx);
 
 void user_start_cpu0(void) {
-	ets_setup_syscalls();
+    ets_setup_syscalls();
 	do_global_ctors();
 	esp_ipc_init();
 	spi_flash_init();
@@ -209,7 +212,7 @@ void user_start_cpu0(void) {
 #if CONFIG_WIFI_ENABLED
     esp_err_t ret = nvs_flash_init(5, 3);
     if (ret != ESP_OK) {
-        printf("nvs_flash_init failed, ret=%d\n", ret);
+        ESP_LOGE(TAG, "nvs_flash_init failed, ret=%d", ret);
     }
 
     system_init();
@@ -226,7 +229,7 @@ void user_start_cpu0(void) {
 	app_main(NULL);
 #endif
 
-	ets_printf("Starting scheduler on PRO CPU.\n");
+	ESP_LOGI(TAG, "Starting scheduler on PRO CPU.");
 	vTaskStartScheduler();
 }
 

components/esp32/heap_alloc_caps.c

@@ -17,6 +17,9 @@
 
 #include "heap_alloc_caps.h"
 #include "spiram.h"
+#include "esp_log.h"
+
+static const char* TAG = "heap_alloc_caps";
 
 /*
 This file, combined with a region allocator that supports tags, solves the problem that the ESP32 has RAM that's 
@@ -147,7 +150,7 @@ static void disable_mem_region(void *from, void *to) {
 			regions[i].xSizeInBytes-=(uint8_t *)regEnd-(uint8_t *)from;
 		} else if (regStart<from && regEnd>to) {
 			//Range punches a hole in the region! We do not support this.
-			ets_printf("%s: region %d: hole punching is not supported!\n", i);
+			ESP_EARLY_LOGE(TAG, "region %d: hole punching is not supported!", i);
 			regions[i].xTag=-1; //Just disable memory region. That'll teach them!
 		}
 	}
@@ -204,12 +207,13 @@ void heap_alloc_caps_init() {
 		}
 	}
 
-#if 1 //Change to 1 to show the regions the heap allocator is initialized with.
-	ets_printf("Initializing heap allocator:\n");
+	ESP_EARLY_LOGI(TAG, "Initializing heap allocator:");
 	for (i=0; regions[i].xSizeInBytes!=0; i++) {
-		if ( regions[i].xTag != -1 ) ets_printf("Region %02d: %08X len %08X tag %d\n", i, (int)regions[i].pucStartAddress, regions[i].xSizeInBytes, regions[i].xTag);
+		if (regions[i].xTag != -1) {
+		    ESP_EARLY_LOGI(TAG, "Region %02d: %08X len %08X tag %d", i,
+		            (int)regions[i].pucStartAddress, regions[i].xSizeInBytes, regions[i].xTag);
+		}
 	}
-#endif
 	//Initialize the malloc implementation.
 	vPortDefineHeapRegionsTagged( regions );
 }

components/log/Kconfig

@@ -0,0 +1,48 @@
+menu "Log output"
+
+choice LOG_DEFAULT_LEVEL
+   bool "Default log verbosity"
+   default LOG_DEFAULT_LEVEL_INFO
+   help
+       Specify how much output to see in logs by default.
+       You can set lower verbosity level at runtime using
+       esp_log_level_set function.
+       
+       Note that this setting limits which log statements
+       are compiled into the program. So setting this to, say,
+       "Warning" would mean that changing log level to "Debug"
+       at runtime will not be possible.
+
+config LOG_DEFAULT_LEVEL_NONE
+   bool "No output"
+config LOG_DEFAULT_LEVEL_ERROR
+   bool "Error"
+config LOG_DEFAULT_LEVEL_WARN
+   bool "Warning"
+config LOG_DEFAULT_LEVEL_INFO
+   bool "Info"
+config LOG_DEFAULT_LEVEL_DEBUG
+   bool "Debug"
+config LOG_DEFAULT_LEVEL_VERBOSE
+   bool "Verbose"
+endchoice
+
+config LOG_DEFAULT_LEVEL
+	int
+	default 0 if LOG_DEFAULT_LEVEL_NONE
+	default 1 if LOG_DEFAULT_LEVEL_ERROR
+	default 2 if LOG_DEFAULT_LEVEL_WARN
+	default 3 if LOG_DEFAULT_LEVEL_INFO
+	default 4 if LOG_DEFAULT_LEVEL_DEBUG
+	default 5 if LOG_DEFAULT_LEVEL_VERBOSE
+
+config LOG_COLORS
+   bool "Use ANSI terminal colors in log output"
+   default "y"
+   help
+      Enable ANSI terminal color codes in bootloader output.
+
+      In order to view these, your terminal program must support ANSI color codes.
+
+
+endmenu

components/log/component.mk

@@ -0,0 +1,3 @@
+COMPONENT_ADD_INCLUDEDIRS := include
+
+include $(IDF_PATH)/make/component_common.mk

components/log/include/esp_log.h

@@ -16,6 +16,8 @@
 #define __ESP_LOG_H__
 
 #include <stdint.h>
+#include <stdarg.h>
+#include "sdkconfig.h"
 
 #ifdef __cplusplus
 extern "C" {
@@ -24,6 +26,20 @@ extern "C" {
 /**
  * @brief Logging library
  *
+ * Log library has two ways of managing log verbosity: compile time, set via
+ * menuconfig, and runtime, using esp_log_set_level function.
+ *
+ * At compile time, filtering is done using CONFIG_LOG_DEFAULT_LEVEL macro, set via
+ * menuconfig. All logging statments for levels higher than CONFIG_LOG_DEFAULT_LEVEL
+ * will be removed by the preprocessor.
+ *
+ * At run time, all logs below CONFIG_LOG_DEFAULT_LEVEL are enabled by default.
+ * esp_log_set_level function may be used to set logging level per module.
+ * Modules are identified by their tags, which are human-readable ASCII
+ * zero-terminated strings.
+ *
+ * How to use this library:
+ *
  * In each C file which uses logging functionality, define TAG variable like this:
  *
  *      static const char* TAG = "MyModule";
@@ -32,31 +48,46 @@ extern "C" {
  *
  *      ESP_LOGW(TAG, "Baud rate error %.1f%%. Requested: %d baud, actual: %d baud", error * 100, baud_req, baud_real);
  *
- * Log filtering happens both at compile time and at runtime.
+ * Several macros are available for different verbosity levels:
+ *
+ *      ESP_LOGE — error
+ *      ESP_LOGW — warning
+ *      ESP_LOGI — info
+ *      ESP_LOGD - debug
+ *      ESP_LOGV - verbose
+ *
+ * Additionally there is an _EARLY_ variant for each of these macros (e.g. ESP_EARLY_LOGE).
+ * These variants can run in startup code, before heap allocator and syscalls
+ * have been initialized.
+ * When compiling bootloader, normal ESP_LOGx macros fall back to the same implementation
+ * as ESP_EARLY_LOGx macros. So the only place where ESP_EARLY_LOGx have to be used explicitly
+ * is the early startup code, such as heap allocator initialization code.
  *
- * At compile time, filtering is done using CONFIG_ESP_LOG_LEVEL macro, set via menuconfig.
- * All logging statments for levels higher than CONFIG_ESP_LOG_LEVEL will be removed by the preprocessor.
+ * (Note that such distinction would not have been necessary if we would have an
+ * ets_vprintf function in the ROM. Then it would be possible to switch implementation
+ * from _EARLY version to normal version on the fly. Unfortunately, ets_vprintf in ROM
+ * has been inlined by the compiler into ets_printf, so it is not accessible outside.)
  *
- * At run time, all logs below CONFIG_ESP_LOG_LEVEL are enabled by default.
- * esp_log_set function may be used to set logging level per tag.
  *
- *      esp_log_set("*", ESP_LOG_ERROR);        // set all components to ERROR level
- *      esp_log_set("wifi", ESP_LOG_WARN);      // enable WARN logs from WiFi stack
- *      esp_log_set("dhcpc", ESP_LOG_INFO);     // enable INFO logs from DHCP client
+ * To configure logging output per module, add calls to esp_log_set_level function:
  *
+ *      esp_log_set_level("*", ESP_LOG_ERROR);        // set all components to ERROR level
+ *      esp_log_set_level("wifi", ESP_LOG_WARN);      // enable WARN logs from WiFi stack
+ *      esp_log_set_level("dhcpc", ESP_LOG_INFO);     // enable INFO logs from DHCP client
  *
  */
 
 
 typedef enum {
-    ESP_LOG_NONE,
-    ESP_LOG_ERROR,
-    ESP_LOG_WARN,
-    ESP_LOG_INFO,
-    ESP_LOG_DEBUG,
-    ESP_LOG_VERBOSE
+    ESP_LOG_NONE,       // No log output
+    ESP_LOG_ERROR,      // Critical errors, software module can not recover on its own
+    ESP_LOG_WARN,       // Error conditions from which recovery measures have been taken
+    ESP_LOG_INFO,       // Information messages which describe normal flow of events
+    ESP_LOG_DEBUG,      // Extra information which is not necessary for normal use (values, pointers, sizes, etc).
+    ESP_LOG_VERBOSE     // Bigger chunks of debugging information, or frequent messages which can potentially flood the output.
 } esp_log_level_t;
 
+typedef int (*vprintf_like_t)(const char *, va_list);
 
 /**
  * @brief Set log level for given tag
@@ -64,52 +95,134 @@ typedef enum {
  * If logging for given component has already been enabled, changes previous setting.
  *
  * @param tag Tag of the log entries to enable. Must be a non-NULL zero terminated string.
- *            Value "*" means that all tags are affected.
+ *            Value "*" resets log level for all tags to the given value.
  *
  * @param level  Selects log level to enable. Only logs at this and lower levels will be shown.
  */
-void esp_log_set(const char* tag, esp_log_level_t level);
+void esp_log_level_set(const char* tag, esp_log_level_t level);
+
+/**
+ * @brief Set function used to output log entries
+ *
+ * By default, log output goes to UART0. This function can be used to redirect log
+ * output to some other destination, such as file or network.
+ *
+ * @param func Function used for output. Must have same signature as vprintf.
+ */
+void esp_log_set_vprintf(vprintf_like_t func);
 
 /**
  * @brief Write message into the log
  *
  * This function is not intended to be used directly. Instead, use one of
  * ESP_LOGE, ESP_LOGW, ESP_LOGI, ESP_LOGD, ESP_LOGV macros.
+ *
+ * This function or these macros should not be used from an interrupt.
  */
 void esp_log_write(esp_log_level_t level, const char* tag, const char* format, ...) __attribute__ ((format (printf, 3, 4)));
-#ifndef CONFIG_ESP_LOG_LEVEL
-#define CONFIG_ESP_LOG_LEVEL ESP_LOG_NONE
-#endif
 
-#if (CONFIG_ESP_LOG_LEVEL < ESP_LOG_ERROR)
-#define ESP_LOGE( tag, format, ... )  esp_log_write(ESP_LOG_ERROR, tag, format, ##__VA_ARGS__)
+
+/**
+ * @brief Function which returns timestamp to be used in log output
+ *
+ * This function is used in expansion of ESP_LOGx macros.
+ * In the 2nd stage bootloader, and at early application startup stage
+ * this function uses CPU cycle counter as time source. Later when
+ * FreeRTOS scheduler start running, it switches to FreeRTOS tick count.
+ *
+ * For now, we ignore millisecond counter overflow.
+ *
+ * @return timestamp, in milliseconds
+ */
+uint32_t esp_log_timestamp();
+
+
+#if CONFIG_LOG_COLORS
+#define LOG_COLOR_BLACK   "30"
+#define LOG_COLOR_RED     "31"
+#define LOG_COLOR_GREEN   "32"
+#define LOG_COLOR_BROWN   "33"
+#define LOG_COLOR_BLUE    "34"
+#define LOG_COLOR_PURPLE  "35"
+#define LOG_COLOR_CYAN    "36"
+#define LOG_COLOR(COLOR)  "\033[0;"COLOR"m"
+#define LOG_BOLD(COLOR)   "\033[1;"COLOR"m"
+#define LOG_RESET_COLOR   "\033[0m"
+#define LOG_COLOR_E       LOG_COLOR(LOG_COLOR_RED)
+#define LOG_COLOR_W       LOG_COLOR(LOG_COLOR_BROWN)
+#define LOG_COLOR_I       LOG_COLOR(LOG_COLOR_GREEN)
+#define LOG_COLOR_D
+#define LOG_COLOR_V
+#else //CONFIG_LOG_COLORS
+#define LOG_COLOR_E
+#define LOG_COLOR_W
+#define LOG_COLOR_I
+#define LOG_COLOR_D
+#define LOG_COLOR_V
+#define LOG_RESET_COLOR
+#endif //CONFIG_LOG_COLORS
+
+#define LOG_FORMAT(letter, format)  LOG_COLOR_ ## letter #letter " (%d) %s: " format LOG_RESET_COLOR "\n"
+
+#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_ERROR)
+#define ESP_EARLY_LOGE( tag, format, ... )  ets_printf(LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#ifndef BOOTLOADER_BUILD
+#define ESP_LOGE( tag, format, ... )  esp_log_write(ESP_LOG_ERROR, tag, LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#else
+#define ESP_LOGE( tag, format, ... )  ESP_EARLY_LOGE( tag, format, ##__VA_ARGS__)
+#endif  // BOOTLOADER_BUILD
 #else
 #define ESP_LOGE( tag, format, ... )
+#define ESP_EARLY_LOGE( tag, format, ... )
 #endif
 
-#if (CONFIG_ESP_LOG_LEVEL < ESP_LOG_WARN)
-#define ESP_LOGW( tag, format, ... )  esp_log_write(ESP_LOG_WARN, tag, format, ##__VA_ARGS__)
+#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_WARN)
+#define ESP_EARLY_LOGW( tag, format, ... )  ets_printf(LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#ifndef BOOTLOADER_BUILD
+#define ESP_LOGW( tag, format, ... )  esp_log_write(ESP_LOG_WARN, tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#else
+#define ESP_LOGW( tag, format, ... )  ESP_EARLY_LOGW( tag, format, ##__VA_ARGS__)
+#endif  // BOOTLOADER_BUILD
 #else
 #define ESP_LOGW( tag, format, ... )
+#define ESP_EARLY_LOGW( tag, format, ... )
 #endif
 
-#if (CONFIG_ESP_LOG_LEVEL < ESP_LOG_INFO)
-#define ESP_LOGI( tag, format, ... )  esp_log_write(ESP_LOG_INFO, tag, format, ##__VA_ARGS__)
+#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_INFO)
+#define ESP_EARLY_LOGI( tag, format, ... )  ets_printf(LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#ifndef BOOTLOADER_BUILD
+#define ESP_LOGI( tag, format, ... )  esp_log_write(ESP_LOG_INFO, tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#else
+#define ESP_LOGI( tag, format, ... )  ESP_EARLY_LOGI( tag, format, ##__VA_ARGS__)
+#endif  //BOOTLOADER_BUILD
 #else
 #define ESP_LOGI( tag, format, ... )
+#define ESP_EARLY_LOGI( tag, format, ... )
 #endif
 
 
-#if (CONFIG_ESP_LOG_LEVEL < ESP_LOG_DEBUG)
-#define ESP_LOGD( tag, format, ... )  esp_log_write(ESP_LOG_DEBUG, tag, format, ##__VA_ARGS__)
+#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_DEBUG)
+#define ESP_EARLY_LOGD( tag, format, ... )  ets_printf(LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#ifndef BOOTLOADER_BUILD
+#define ESP_LOGD( tag, format, ... )  esp_log_write(ESP_LOG_DEBUG, tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#else
+#define ESP_LOGD( tag, format, ... )  ESP_EARLY_LOGD(tag, format, ##__VA_ARGS__)
+#endif  // BOOTLOADER_BUILD
 #else
 #define ESP_LOGD( tag, format, ... )
+#define ESP_EARLY_LOGD( tag, format, ... )
 #endif
 
-#if (CONFIG_ESP_LOG_VERBOSE < ESP_LOG_ERROR)
-#define ESP_LOGV( tag, format, ... )  esp_log_write(ESP_LOG_VERBOSE, tag, format, ##__VA_ARGS__)
+#if (CONFIG_LOG_DEFAULT_LEVEL >= ESP_LOG_VERBOSE)
+#define ESP_EARLY_LOGV( tag, format, ... )  ets_printf(LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#ifndef BOOTLOADER_BUILD
+#define ESP_LOGV( tag, format, ... )  esp_log_write(ESP_LOG_VERBOSE, tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
+#else
+#define ESP_LOGV( tag, format, ... )  ESP_EARLY_LOGV(tag, format, ##__VA_ARGS__)
+#endif  // BOOTLOADER_BUILD
 #else
 #define ESP_LOGV( tag, format, ... )
+#define ESP_EARLY_LOGV( tag, format, ... )
 #endif
 
 #ifdef __cplusplus

components/log/log.c

@@ -0,0 +1,283 @@
+// Copyright 2015-2016 Espressif Systems (Shanghai) PTE LTD
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+/*
+ * Log library — implementation notes.
+ *
+ * Log library stores all tags provided to esp_log_set_level as a linked
+ * list. See uncached_tag_entry_t structure.
+ *
+ * To avoid looking up log level for given tag each time message is
+ * printed, this library caches pointers to tags. Because the suggested
+ * way of creating tags uses one 'TAG' constant per file, this caching
+ * should be effective. Cache is a binary min-heap of cached_tag_entry_t
+ * items, ordering is done on 'generation' member. In this context,
+ * generation is an integer which is incremented each time an operation
+ * with cache is performed. When cache is full, new item is inserted in
+ * place of an oldest item (that is, with smallest 'generation' value).
+ * After that, bubble-down operation is performed to fix ordering in the
+ * min-heap.
+ *
+ * The potential problem with wrap-around of cache generation counter is
+ * ignored for now. This will happen if someone happens to output more
+ * than 4 billion log entries, at which point wrap-around will not be
+ * the biggest problem.
+ *
+ */
+
+#ifndef BOOTLOADER_BUILD
+#include <freertos/FreeRTOS.h>
+#include <freertos/FreeRTOSConfig.h>
+#include <freertos/task.h>
+#include <freertos/semphr.h>
+#endif
+
+#include "esp_attr.h"
+#include "xtensa/hal.h"
+#include "soc/soc.h"
+#include <stdbool.h>
+#include <stdarg.h>
+#include <string.h>
+#include <stdlib.h>
+#include <stdio.h>
+#include "esp_log.h"
+
+
+#ifndef BOOTLOADER_BUILD
+
+#define TAG_CACHE_SIZE 32
+#define MAX_MUTEX_WAIT_TICKS ((10 + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS)
+
+typedef struct {
+    const char* tag;
+    uint32_t level : 3;
+    uint32_t generation : 29;
+} cached_tag_entry_t;
+
+typedef struct uncached_tag_entry_{
+    struct uncached_tag_entry_* next;
+    uint8_t level;  // esp_log_level_t as uint8_t
+    char tag[0];    // beginning of a zero-terminated string
+} uncached_tag_entry_t;
+
+static esp_log_level_t s_default_level = (esp_log_level_t) CONFIG_LOG_DEFAULT_LEVEL;
+static uncached_tag_entry_t* s_head = NULL;
+static uncached_tag_entry_t* s_tail = NULL;
+static cached_tag_entry_t s_cache[TAG_CACHE_SIZE];
+static uint32_t s_cache_max_generation = 0;
+static uint32_t s_cache_entry_count = 0;
+static vprintf_like_t s_print_func = &vprintf;
+static SemaphoreHandle_t s_mutex = NULL;
+
+static inline bool get_cached_log_level(const char* tag, esp_log_level_t* level);
+static inline bool get_uncached_log_level(const char* tag, esp_log_level_t* level);
+static inline void add_to_cache(const char* tag, esp_log_level_t level);
+static void heap_bubble_down(int index);
+static inline void heap_swap(int i, int j);
+static inline bool should_output(esp_log_level_t level_for_message, esp_log_level_t level_for_tag);
+static inline void clear_log_level_list();
+
+void esp_log_set_vprintf(vprintf_like_t func)
+{
+    s_print_func = func;
+}
+
+void esp_log_level_set(const char* tag, esp_log_level_t level)
+{
+    if (!s_mutex) {
+        s_mutex = xSemaphoreCreateMutex();
+    }
+    xSemaphoreTake(&s_mutex, portMAX_DELAY);
+
+    // for wildcard tag, remove all linked list items and clear the cache
+    if (strcmp(tag, "*") == 0) {
+        s_default_level = level;
+        clear_log_level_list();
+        xSemaphoreGive(&s_mutex);
+        return;
+    }
+
+    // allocate new linked list entry and append it to the endo of the list
+    size_t entry_size = offsetof(uncached_tag_entry_t, tag) + strlen(tag) + 1;
+    uncached_tag_entry_t* new_entry = (uncached_tag_entry_t*) malloc(entry_size);
+    if (!new_entry) {
+        xSemaphoreGive(&s_mutex);
+        return;
+    }
+    new_entry->next = NULL;
+    new_entry->level = (uint8_t) level;
+    strcpy(new_entry->tag, tag);
+    if (s_tail) {
+        s_tail->next = new_entry;
+    }
+    s_tail = new_entry;
+    if (!s_head) {
+        s_head = new_entry;
+    }
+    xSemaphoreGive(&s_mutex);
+}
+
+void clear_log_level_list()
+{
+    for (uncached_tag_entry_t* it = s_head; it != NULL; ) {
+        uncached_tag_entry_t* next = it->next;
+        free(it);
+        it = next;
+    }
+
+    s_cache_entry_count = 0;
+    s_cache_max_generation = 0;
+}
+
+void IRAM_ATTR esp_log_write(esp_log_level_t level,
+        const char* tag,
+        const char* format, ...)
+{
+    if (!s_mutex) {
+        s_mutex = xSemaphoreCreateMutex();
+    }
+    if (xSemaphoreTake(&s_mutex, MAX_MUTEX_WAIT_TICKS) == pdFALSE) {
+        return;
+    }
+    esp_log_level_t level_for_tag;
+    // Look for the tag in cache first, then in the linked list of all tags
+    if (!get_cached_log_level(tag, &level_for_tag)) {
+        if (!get_uncached_log_level(tag, &level_for_tag)) {
+            level_for_tag = s_default_level;
+        }
+        add_to_cache(tag, level_for_tag);
+    }
+    xSemaphoreGive(&s_mutex);
+    if (!should_output(level, level_for_tag)) {
+        return;
+    }
+
+    va_list list;
+    va_start(list, format);
+    (*s_print_func)(format, list);
+    va_end(list);
+}
+
+static inline bool get_cached_log_level(const char* tag, esp_log_level_t* level)
+{
+    // Look for `tag` in cache
+    int i;
+    for (i = 0; i < s_cache_entry_count; ++i) {
+        if (s_cache[i].tag == tag) {
+            break;
+        }
+    }
+    if (i == s_cache_entry_count) { // Not found in cache
+        return false;
+    }
+    // Return level from cache
+    *level = (esp_log_level_t) s_cache[i].level;
+    // Update item generation
+    s_cache[i].generation = s_cache_max_generation++;
+    // Restore heap ordering
+    heap_bubble_down(i);
+    return true;
+}
+
+static inline void add_to_cache(const char* tag, esp_log_level_t level)
+{
+    uint32_t generation = s_cache_max_generation++;
+    // First consider the case when cache is not filled yet.
+    // In this case, just add new entry at the end.
+    // This happens to satisfy binary min-heap ordering.
+    if (s_cache_entry_count < TAG_CACHE_SIZE) {
+        s_cache[s_cache_entry_count] = (cached_tag_entry_t) {
+            .generation = generation,
+            .level = level,
+            .tag = tag
+        };
+        ++s_cache_entry_count;
+        return;
+    }
+
+    // Cache is full, so we replace the oldest entry (which is at index 0
+    // because this is a min-heap) with the new one, and do bubble-down
+    // operation to restore min-heap ordering.
+    s_cache[0] = (cached_tag_entry_t) {
+        .tag = tag,
+        .level = level,
+        .generation = generation
+    };
+    heap_bubble_down(0);
+}
+
+static inline bool get_uncached_log_level(const char* tag, esp_log_level_t* level)
+{
+    // Walk the linked list of all tags and see if given tag is present in the list.
+    // This is slow because tags are compared as strings.
+    for (uncached_tag_entry_t* it = s_head; it != NULL; ++it) {
+        if (strcmp(tag, it->tag) == 0) {
+            *level = it->level;
+            return true;
+        }
+    }
+    return false;
+}
+
+static inline bool should_output(esp_log_level_t level_for_message, esp_log_level_t level_for_tag)
+{
+    return level_for_message <= level_for_tag;
+}
+
+static void heap_bubble_down(int index)
+{
+    while (index < TAG_CACHE_SIZE / 2) {
+        int left_index = index * 2 + 1;
+        int right_index = left_index + 1;
+        int next = (s_cache[left_index].generation < s_cache[right_index].generation) ? left_index : right_index;
+        heap_swap(index, next);
+        index = next;
+    }
+}
+
+static inline void heap_swap(int i, int j)
+{
+    cached_tag_entry_t tmp = s_cache[i];
+    s_cache[i] = s_cache[j];
+    s_cache[j] = tmp;
+}
+#endif //BOOTLOADER_BUILD
+
+inline uint32_t esp_log_early_timestamp()
+{
+    return xthal_get_ccount() / (CPU_CLK_FREQ_ROM / 1000);
+}
+
+#ifndef BOOTLOADER_BUILD
+
+uint32_t IRAM_ATTR esp_log_timestamp()
+{
+    if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) {
+        return esp_log_early_timestamp();
+    }
+    static uint32_t base = 0;
+    if (base == 0) {
+        base = esp_log_early_timestamp();
+    }
+    return base + xTaskGetTickCount() * configTICK_RATE_HZ;
+}
+
+#else
+
+uint32_t esp_log_timestamp()
+{
+    return esp_log_early_timestamp();
+}
+
+#endif //BOOTLOADER_BUILD