diff --git a/components/bootloader/Kconfig.projbuild b/components/bootloader/Kconfig.projbuild index 74028b6e90..8d5f667216 100644 --- a/components/bootloader/Kconfig.projbuild +++ b/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 diff --git a/components/bootloader/src/Makefile b/components/bootloader/src/Makefile index b6b0c1af02..065593ccbf 100644 --- a/components/bootloader/src/Makefile +++ b/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 diff --git a/components/bootloader/src/main/bootloader_log.h b/components/bootloader/src/main/bootloader_log.h deleted file mode 100644 index 1f7ec62ad5..0000000000 --- a/components/bootloader/src/main/bootloader_log.h +++ /dev/null @@ -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__ */ diff --git a/components/bootloader/src/main/bootloader_start.c b/components/bootloader/src/main/bootloader_start.c index 2dbf0e8269..f56bc5e6b5 100644 --- a/components/bootloader/src/main/bootloader_start.c +++ b/components/bootloader/src/main/bootloader_start.c @@ -16,6 +16,7 @@ #include #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 } diff --git a/components/bootloader/src/main/component.mk b/components/bootloader/src/main/component.mk index 1671095f1b..8c8ea4cb63 100644 --- a/components/bootloader/src/main/component.mk +++ b/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 diff --git a/components/bootloader/src/main/flash_encrypt.c b/components/bootloader/src/main/flash_encrypt.c index d5f105f9cc..9e774e087c 100644 --- a/components/bootloader/src/main/flash_encrypt.c +++ b/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; } } diff --git a/components/bootloader/src/main/secure_boot.c b/components/bootloader/src/main/secure_boot.c index 97ddd1a8de..0e7d581d9f 100644 --- a/components/bootloader/src/main/secure_boot.c +++ b/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; } diff --git a/components/esp32/cpu_start.c b/components/esp32/cpu_start.c index e1a5f027b7..cfc628b12b 100644 --- a/components/esp32/cpu_start.c +++ b/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(); } diff --git a/components/esp32/heap_alloc_caps.c b/components/esp32/heap_alloc_caps.c index e816175b94..5b3ec33dba 100644 --- a/components/esp32/heap_alloc_caps.c +++ b/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 (regStartto) { //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 ); } diff --git a/components/log/Kconfig b/components/log/Kconfig new file mode 100644 index 0000000000..1627ea1830 --- /dev/null +++ b/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 diff --git a/components/log/component.mk b/components/log/component.mk new file mode 100755 index 0000000000..ef497a7ecb --- /dev/null +++ b/components/log/component.mk @@ -0,0 +1,3 @@ +COMPONENT_ADD_INCLUDEDIRS := include + +include $(IDF_PATH)/make/component_common.mk diff --git a/components/log/include/esp_log.h b/components/log/include/esp_log.h index e8ecf875b3..32f6d0bb30 100644 --- a/components/log/include/esp_log.h +++ b/components/log/include/esp_log.h @@ -16,6 +16,8 @@ #define __ESP_LOG_H__ #include +#include +#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: * - * 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. + * ESP_LOGE — error + * ESP_LOGW — warning + * ESP_LOGI — info + * ESP_LOGD - debug + * ESP_LOGV - verbose * - * 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. + * 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. * - * 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 + * (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.) * * + * 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 diff --git a/components/log/log.c b/components/log/log.c new file mode 100644 index 0000000000..bd6df01b28 --- /dev/null +++ b/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 +#include +#include +#include +#endif + +#include "esp_attr.h" +#include "xtensa/hal.h" +#include "soc/soc.h" +#include +#include +#include +#include +#include +#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