Crash_Override/OVMS3-idf
1
0
Fork 0
Code Issues Pull requests Projects Releases Wiki Activity

components/log: fix bugs, add options to override log level for files, components, and bootloader

Browse source
This commit is contained in:
Ivan Grokhotkov 2016-09-18 20:24:31 +08:00
parent b0683b0bb4
commit 69278b28bf
3 changed files with 138 additions and 89 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

28
components/bootloader/Kconfig.projbuild
View file

@ -1,3 +1,31 @@
menu "Bootloader config"
choice LOG_BOOTLOADER_LEVEL
bool "Bootloader log verbosity"
default LOG_BOOTLOADER_LEVEL_WARN
help
Specify how much output to see in bootloader logs.
config LOG_BOOTLOADER_LEVEL_NONE
bool "No output"
config LOG_BOOTLOADER_LEVEL_ERROR
bool "Error"
config LOG_BOOTLOADER_LEVEL_WARN
bool "Warning"
config LOG_BOOTLOADER_LEVEL_INFO
bool "Info"
config LOG_BOOTLOADER_LEVEL_DEBUG
bool "Debug"
config LOG_BOOTLOADER_LEVEL_VERBOSE
bool "Verbose"
endchoice
config LOG_BOOTLOADER_LEVEL
int
default 0 if LOG_BOOTLOADER_LEVEL_NONE
default 1 if LOG_BOOTLOADER_LEVEL_ERROR
default 2 if LOG_BOOTLOADER_LEVEL_WARN
default 3 if LOG_BOOTLOADER_LEVEL_INFO
default 4 if LOG_BOOTLOADER_LEVEL_DEBUG
default 5 if LOG_BOOTLOADER_LEVEL_VERBOSE
endmenu

65
components/log/include/esp_log.h
View file

@ -68,8 +68,17 @@ extern "C" {
* 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 override default verbosity level at file or component scope, define LOG_LOCAL_LEVEL macro.
* At file scope, define it before including esp_log.h, e.g.:
*
* To configure logging output per module, add calls to esp_log_set_level function:
* #define LOG_LOCAL_LEVEL ESP_LOG_VERBOSE
* #include "esp_log.h"
*
* At component scope, define it in component makefile:
*
* CFLAGS += -D LOG_LOCAL_LEVEL=ESP_LOG_DEBUG
*
* To configure logging output per module at runtime, 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
@ -162,68 +171,50 @@ uint32_t esp_log_timestamp();
#define LOG_RESET_COLOR
#endif //CONFIG_LOG_COLORS
#ifndef LOG_LOCAL_LEVEL
#ifndef BOOTLOADER_BUILD
#define LOG_LOCAL_LEVEL ((esp_log_level_t) CONFIG_LOG_DEFAULT_LEVEL)
#else
#define LOG_LOCAL_LEVEL ((esp_log_level_t) CONFIG_LOG_BOOTLOADER_LEVEL)
#endif
#endif
#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__)
#define ESP_EARLY_LOGE( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_ERROR) { 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__)
#define ESP_LOGE( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_ERROR) { 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_LOG_DEFAULT_LEVEL >= ESP_LOG_WARN)
#define ESP_EARLY_LOGW( tag, format, ... ) ets_printf(LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
#define ESP_EARLY_LOGW( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_WARN) { 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__)
#define ESP_LOGW( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_WARN) { 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_LOG_DEFAULT_LEVEL >= ESP_LOG_INFO)
#define ESP_EARLY_LOGI( tag, format, ... ) ets_printf(LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
#define ESP_EARLY_LOGI( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_INFO) { 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__)
#define ESP_LOGI( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_INFO) { 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_LOG_DEFAULT_LEVEL >= ESP_LOG_DEBUG)
#define ESP_EARLY_LOGD( tag, format, ... ) ets_printf(LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
#define ESP_EARLY_LOGD( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_DEBUG) { 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__)
#define ESP_LOGD( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_DEBUG) { 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_LOG_DEFAULT_LEVEL >= ESP_LOG_VERBOSE)
#define ESP_EARLY_LOGV( tag, format, ... ) ets_printf(LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__)
#define ESP_EARLY_LOGV( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_VERBOSE) { 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__)
#define ESP_LOGV( tag, format, ... ) if (LOG_LOCAL_LEVEL >= ESP_LOG_VERBOSE) { 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
}

134
components/log/log.c
View file

@ -51,13 +51,21 @@
#include <string.h>
#include <stdlib.h>
#include <stdio.h>
#include <assert.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)
// Number of tags to be cached. Must be 2**n - 1, n >= 2.
#define TAG_CACHE_SIZE 31
// Maximum time to wait for the mutex in a logging statement.
#define MAX_MUTEX_WAIT_MS 10
#define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS)
// Uncomment this to enable consistency checks and cache statistics in this file.
// #define LOG_BUILTIN_CHECKS
typedef struct {
const char* tag;
@ -71,14 +79,18 @@ typedef struct uncached_tag_entry_{
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 esp_log_level_t s_log_default_level = (esp_log_level_t) CONFIG_LOG_DEFAULT_LEVEL;
static uncached_tag_entry_t* s_log_tags_head = NULL;
static uncached_tag_entry_t* s_log_tags_tail = NULL;
static cached_tag_entry_t s_log_cache[TAG_CACHE_SIZE];
static uint32_t s_log_cache_max_generation = 0;
static uint32_t s_log_cache_entry_count = 0;
static vprintf_like_t s_log_print_func = &vprintf;
static SemaphoreHandle_t s_log_mutex = NULL;
#ifdef LOG_BUILTIN_CHECKS
static uint32_t s_log_cache_misses = 0;
#endif
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);
@ -90,21 +102,21 @@ static inline void clear_log_level_list();
void esp_log_set_vprintf(vprintf_like_t func)
{
s_print_func = func;
s_log_print_func = func;
}
void esp_log_level_set(const char* tag, esp_log_level_t level)
{
if (!s_mutex) {
s_mutex = xSemaphoreCreateMutex();
if (!s_log_mutex) {
s_log_mutex = xSemaphoreCreateMutex();
}
xSemaphoreTake(&s_mutex, portMAX_DELAY);
xSemaphoreTake(s_log_mutex, portMAX_DELAY);
// for wildcard tag, remove all linked list items and clear the cache
if (strcmp(tag, "*") == 0) {
s_default_level = level;
s_log_default_level = level;
clear_log_level_list();
xSemaphoreGive(&s_mutex);
xSemaphoreGive(s_log_mutex);
return;
}
@ -112,60 +124,68 @@ void esp_log_level_set(const char* tag, esp_log_level_t level)
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);
xSemaphoreGive(s_log_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;
if (s_log_tags_tail) {
s_log_tags_tail->next = new_entry;
}
s_tail = new_entry;
if (!s_head) {
s_head = new_entry;
s_log_tags_tail = new_entry;
if (!s_log_tags_head) {
s_log_tags_head = new_entry;
}
xSemaphoreGive(&s_mutex);
xSemaphoreGive(s_log_mutex);
}
void clear_log_level_list()
{
for (uncached_tag_entry_t* it = s_head; it != NULL; ) {
for (uncached_tag_entry_t* it = s_log_tags_head; it != NULL; ) {
uncached_tag_entry_t* next = it->next;
free(it);
it = next;
}
s_log_tags_tail = NULL;
s_log_tags_head = NULL;
s_log_cache_entry_count = 0;
s_log_cache_max_generation = 0;
#ifdef LOG_BUILTIN_CHECKS
s_log_cache_misses = 0;
#endif
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 (!s_log_mutex) {
s_log_mutex = xSemaphoreCreateMutex();
}
if (xSemaphoreTake(&s_mutex, MAX_MUTEX_WAIT_TICKS) == pdFALSE) {
if (xSemaphoreTake(s_log_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;
level_for_tag = s_log_default_level;
}
add_to_cache(tag, level_for_tag);
#ifdef LOG_BUILTIN_CHECKS
++s_log_cache_misses;
#endif
}
xSemaphoreGive(&s_mutex);
xSemaphoreGive(s_log_mutex);
if (!should_output(level, level_for_tag)) {
return;
}
va_list list;
va_start(list, format);
(*s_print_func)(format, list);
(*s_log_print_func)(format, list);
va_end(list);
}
@ -173,43 +193,53 @@ 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) {
for (i = 0; i < s_log_cache_entry_count; ++i) {
#ifdef LOG_BUILTIN_CHECKS
assert(i == 0 || s_log_cache[(i - 1) / 2].generation < s_log_cache[i].generation);
#endif
if (s_log_cache[i].tag == tag) {
break;
}
}
if (i == s_cache_entry_count) { // Not found in cache
if (i == s_log_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);
*level = (esp_log_level_t) s_log_cache[i].level;
// If cache has been filled, start taking ordering into account
// (other options are: dynamically resize cache, add "dummy" entries
// to the cache; this option was chosen because code is much simpler,
// and the unfair behavior of cache will show it self at most once, when
// it has just been filled)
if (s_log_cache_entry_count == TAG_CACHE_SIZE) {
// Update item generation
s_log_cache[i].generation = s_log_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++;
uint32_t generation = s_log_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) {
if (s_log_cache_entry_count < TAG_CACHE_SIZE) {
s_log_cache[s_log_cache_entry_count] = (cached_tag_entry_t) {
.generation = generation,
.level = level,
.tag = tag
};
++s_cache_entry_count;
++s_log_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) {
s_log_cache[0] = (cached_tag_entry_t) {
.tag = tag,
.level = level,
.generation = generation
@ -221,7 +251,7 @@ static inline bool get_uncached_log_level(const char* tag, esp_log_level_t* leve
{
// 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) {
for (uncached_tag_entry_t* it = s_log_tags_head; it != NULL; it = it->next) {
if (strcmp(tag, it->tag) == 0) {
*level = it->level;
return true;
@ -240,7 +270,7 @@ 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;
int next = (s_log_cache[left_index].generation < s_log_cache[right_index].generation) ? left_index : right_index;
heap_swap(index, next);
index = next;
}
@ -248,13 +278,13 @@ static void heap_bubble_down(int index)
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;
cached_tag_entry_t tmp = s_log_cache[i];
s_log_cache[i] = s_log_cache[j];
s_log_cache[j] = tmp;
}
#endif //BOOTLOADER_BUILD
inline uint32_t esp_log_early_timestamp()
inline IRAM_ATTR uint32_t esp_log_early_timestamp()
{
return xthal_get_ccount() / (CPU_CLK_FREQ_ROM / 1000);
}
@ -275,7 +305,7 @@ uint32_t IRAM_ATTR esp_log_timestamp()
#else
uint32_t esp_log_timestamp()
uint32_t IRAM_ATTR esp_log_timestamp()
{
return esp_log_early_timestamp();
}