diff --git a/components/log/Kconfig b/components/log/Kconfig new file mode 100644 index 00000000..43e3a523 --- /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/README.rst b/components/log/README.rst new file mode 100644 index 00000000..034c32d7 --- /dev/null +++ b/components/log/README.rst @@ -0,0 +1,68 @@ +Logging library +=============== + +Overview +-------- + +Log library has two ways of managing log verbosity: compile time, set via menuconfig; and runtime, using :cpp:func:`esp_log_level_set` function. + +The log levels are Error, Warning, Info, Debug, and Verbose (from lowest to highest level of verbosity). + +At compile time, filtering is done using :ref:`CONFIG_LOG_DEFAULT_LEVEL` option, set via menuconfig. All logging statements for levels higher than :ref:`CONFIG_LOG_DEFAULT_LEVEL` will be removed by the preprocessor. + +At run time, all logs below :ref:`CONFIG_LOG_DEFAULT_LEVEL` are enabled by default. :cpp:func:`esp_log_level_set` function may be used to reduce logging level per module. Modules are identified by their tags, which are human-readable ASCII zero-terminated strings. + +Note that :cpp:func:`esp_log_level_set` can not increase logging level beyound that set by :ref:`CONFIG_LOG_DEFAULT_LEVEL`. To increase log level for a specific file at compile time, `LOG_LOCAL_LEVEL` macro can be used (see below for details). + +How to use this library +----------------------- + +In each C file which uses logging functionality, define TAG variable like this: + +.. code-block:: c + + static const char* TAG = "MyModule"; + +then use one of logging macros to produce output, e.g: + +.. code-block:: c + + ESP_LOGW(TAG, "Baud rate error %.1f%%. Requested: %d baud, actual: %d baud", error * 100, baud_req, baud_real); + +Several macros are available for different verbosity levels: + +* ``ESP_LOGE`` - error (lowest) +* ``ESP_LOGW`` - warning +* ``ESP_LOGI`` - info +* ``ESP_LOGD`` - debug +* ``ESP_LOGV`` - verbose (highest) + +Additionally there is an ``_EARLY`` variant for each of these macros (e.g. :c:macro:`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. + +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.: + +.. code-block:: c + + #define LOG_LOCAL_LEVEL ESP_LOG_VERBOSE + #include "esp_log.h" + + +At component scope, define it in component makefile: + +.. code-block:: make + + CFLAGS += -D LOG_LOCAL_LEVEL=ESP_LOG_DEBUG + +To configure logging output per module at runtime, add calls to :cpp:func:`esp_log_level_set` function: + +.. code-block:: c + + esp_log_level_set("*", ESP_LOG_ERROR); // set all components to ERROR level + esp_log_level_set("wifi", ESP_LOG_WARN); // enable WARN logs from WiFi stack + esp_log_level_set("dhcpc", ESP_LOG_INFO); // enable INFO logs from DHCP client + +Logging to Host via JTAG +^^^^^^^^^^^^^^^^^^^^^^^^ + +By default logging library uses vprintf-like function to write formatted output to dedicated UART. By calling a simple API, all log output may be routed to JTAG instead, making logging several times faster. For details please refer to section :ref:`app_trace-logging-to-host`. + diff --git a/components/log/component.mk b/components/log/component.mk new file mode 100755 index 00000000..c2c4c03a --- /dev/null +++ b/components/log/component.mk @@ -0,0 +1,5 @@ +# +# Component Makefile +# +# (Uses default behaviour of compiling all source files in directory, adding 'include' to include path.) + diff --git a/components/log/include/esp_log.h b/components/log/include/esp_log.h new file mode 100644 index 00000000..e57aabbd --- /dev/null +++ b/components/log/include/esp_log.h @@ -0,0 +1,319 @@ +// 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 __ESP_LOG_H__ +#define __ESP_LOG_H__ + +#include +#include +#include "sdkconfig.h" +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Log level + * + */ +typedef enum { + 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 + * + * If logging for given component has already been enabled, changes previous setting. + * + * Note that this function can not raise log level above the level set using + * CONFIG_LOG_DEFAULT_LEVEL setting in menuconfig. + * + * To raise log level above the default one for a given file, define + * LOG_LOCAL_LEVEL to one of the ESP_LOG_* values, before including + * esp_log.h in this file. + * + * @param tag Tag of the log entries to enable. Must be a non-NULL zero terminated string. + * Value "*" resets log level for all tags to the given value. + * + * @param level Selects log level to enable. Only logs at this and lower verbosity + * levels will be shown. + */ +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. Returns the original + * log handler, which may be necessary to return output to the previous destination. + * + * @param func new Function used for output. Must have same signature as vprintf. + * + * @return func old Function used for output. + */ +vprintf_like_t esp_log_set_vprintf(vprintf_like_t func); + +/** + * @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(void); + +/** + * @brief Function which returns timestamp to be used in log output + * + * This function uses HW cycle counter and does not depend on OS, + * so it can be safely used after application crash. + * + * @return timestamp, in milliseconds + */ +uint32_t esp_log_early_timestamp(void); + +/** + * @brief Write message into the log + * + * 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))); + +/** @cond */ + +#include "esp_log_internal.h" + +#ifndef LOG_LOCAL_LEVEL +#ifndef BOOTLOADER_BUILD +#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL +#else +#define LOG_LOCAL_LEVEL CONFIG_LOG_BOOTLOADER_LEVEL +#endif +#endif + +/** @endcond */ + +/** + * @brief Log a buffer of hex bytes at specified level, separated into 16 bytes each line. + * + * @param tag description tag + * @param buffer Pointer to the buffer array + * @param buff_len length of buffer in bytes + * @param level level of the log + * + */ +#define ESP_LOG_BUFFER_HEX_LEVEL( tag, buffer, buff_len, level ) \ + do {\ + if ( LOG_LOCAL_LEVEL >= (level) ) { \ + esp_log_buffer_hex_internal( tag, buffer, buff_len, level ); \ + } \ + } while(0) + +/** + * @brief Log a buffer of characters at specified level, separated into 16 bytes each line. Buffer should contain only printable characters. + * + * @param tag description tag + * @param buffer Pointer to the buffer array + * @param buff_len length of buffer in bytes + * @param level level of the log + * + */ +#define ESP_LOG_BUFFER_CHAR_LEVEL( tag, buffer, buff_len, level ) \ + do {\ + if ( LOG_LOCAL_LEVEL >= (level) ) { \ + esp_log_buffer_char_internal( tag, buffer, buff_len, level ); \ + } \ + } while(0) + +/** + * @brief Dump a buffer to the log at specified level. + * + * The dump log shows just like the one below: + * + * W (195) log_example: 0x3ffb4280 45 53 50 33 32 20 69 73 20 67 72 65 61 74 2c 20 |ESP32 is great, | + * W (195) log_example: 0x3ffb4290 77 6f 72 6b 69 6e 67 20 61 6c 6f 6e 67 20 77 69 |working along wi| + * W (205) log_example: 0x3ffb42a0 74 68 20 74 68 65 20 49 44 46 2e 00 |th the IDF..| + * + * It is highly recommend to use terminals with over 102 text width. + * + * @param tag description tag + * @param buffer Pointer to the buffer array + * @param buff_len length of buffer in bytes + * @param level level of the log + */ +#define ESP_LOG_BUFFER_HEXDUMP( tag, buffer, buff_len, level ) \ + do { \ + if ( LOG_LOCAL_LEVEL >= (level) ) { \ + esp_log_buffer_hexdump_internal( tag, buffer, buff_len, level); \ + } \ + } while(0) + +/** + * @brief Log a buffer of hex bytes at Info level + * + * @param tag description tag + * @param buffer Pointer to the buffer array + * @param buff_len length of buffer in bytes + * + * @see ``esp_log_buffer_hex_level`` + * + */ +#define ESP_LOG_BUFFER_HEX(tag, buffer, buff_len) \ + do { \ + if (LOG_LOCAL_LEVEL >= ESP_LOG_INFO) { \ + ESP_LOG_BUFFER_HEX_LEVEL( tag, buffer, buff_len, ESP_LOG_INFO ); \ + }\ + } while(0) + +/** + * @brief Log a buffer of characters at Info level. Buffer should contain only printable characters. + * + * @param tag description tag + * @param buffer Pointer to the buffer array + * @param buff_len length of buffer in bytes + * + * @see ``esp_log_buffer_char_level`` + * + */ +#define ESP_LOG_BUFFER_CHAR(tag, buffer, buff_len) \ + do { \ + if (LOG_LOCAL_LEVEL >= ESP_LOG_INFO) { \ + ESP_LOG_BUFFER_CHAR_LEVEL( tag, buffer, buff_len, ESP_LOG_INFO ); \ + }\ + } while(0) + +/** @cond */ + +//to be back compatible +#define esp_log_buffer_hex ESP_LOG_BUFFER_HEX +#define esp_log_buffer_char ESP_LOG_BUFFER_CHAR + + +#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" + +/** @endcond */ + +/// macro to output logs in startup code, before heap allocator and syscalls have been initialized. log at ``ESP_LOG_ERROR`` level. @see ``printf``,``ESP_LOGE`` +#define ESP_EARLY_LOGE( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_ERROR, E, ##__VA_ARGS__) +/// macro to output logs in startup code at ``ESP_LOG_WARN`` level. @see ``ESP_EARLY_LOGE``,``ESP_LOGE``, ``printf`` +#define ESP_EARLY_LOGW( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_WARN, W, ##__VA_ARGS__) +/// macro to output logs in startup code at ``ESP_LOG_INFO`` level. @see ``ESP_EARLY_LOGE``,``ESP_LOGE``, ``printf`` +#define ESP_EARLY_LOGI( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_INFO, I, ##__VA_ARGS__) +/// macro to output logs in startup code at ``ESP_LOG_DEBUG`` level. @see ``ESP_EARLY_LOGE``,``ESP_LOGE``, ``printf`` +#define ESP_EARLY_LOGD( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_DEBUG, D, ##__VA_ARGS__) +/// macro to output logs in startup code at ``ESP_LOG_VERBOSE`` level. @see ``ESP_EARLY_LOGE``,``ESP_LOGE``, ``printf`` +#define ESP_EARLY_LOGV( tag, format, ... ) ESP_LOG_EARLY_IMPL(tag, format, ESP_LOG_VERBOSE, V, ##__VA_ARGS__) + +#define ESP_LOG_EARLY_IMPL(tag, format, log_level, log_tag_letter, ...) do { \ + if (LOG_LOCAL_LEVEL >= log_level) { \ + ets_printf(LOG_FORMAT(log_tag_letter, format), esp_log_timestamp(), tag, ##__VA_ARGS__); \ + }} while(0) + +#ifndef BOOTLOADER_BUILD +#define ESP_LOGE( tag, format, ... ) ESP_LOG_LEVEL_LOCAL(ESP_LOG_ERROR, tag, format, ##__VA_ARGS__) +#define ESP_LOGW( tag, format, ... ) ESP_LOG_LEVEL_LOCAL(ESP_LOG_WARN, tag, format, ##__VA_ARGS__) +#define ESP_LOGI( tag, format, ... ) ESP_LOG_LEVEL_LOCAL(ESP_LOG_INFO, tag, format, ##__VA_ARGS__) +#define ESP_LOGD( tag, format, ... ) ESP_LOG_LEVEL_LOCAL(ESP_LOG_DEBUG, tag, format, ##__VA_ARGS__) +#define ESP_LOGV( tag, format, ... ) ESP_LOG_LEVEL_LOCAL(ESP_LOG_VERBOSE, tag, format, ##__VA_ARGS__) +#else +/** + * macro to output logs at ESP_LOG_ERROR level. + * + * @param tag tag of the log, which can be used to change the log level by ``esp_log_level_set`` at runtime. + * + * @see ``printf`` + */ +#define ESP_LOGE( tag, format, ... ) ESP_EARLY_LOGE(tag, format, ##__VA_ARGS__) +/// macro to output logs at ``ESP_LOG_WARN`` level. @see ``ESP_LOGE`` +#define ESP_LOGW( tag, format, ... ) ESP_EARLY_LOGW(tag, format, ##__VA_ARGS__) +/// macro to output logs at ``ESP_LOG_INFO`` level. @see ``ESP_LOGE`` +#define ESP_LOGI( tag, format, ... ) ESP_EARLY_LOGI(tag, format, ##__VA_ARGS__) +/// macro to output logs at ``ESP_LOG_DEBUG`` level. @see ``ESP_LOGE`` +#define ESP_LOGD( tag, format, ... ) ESP_EARLY_LOGD(tag, format, ##__VA_ARGS__) +/// macro to output logs at ``ESP_LOG_VERBOSE`` level. @see ``ESP_LOGE`` +#define ESP_LOGV( tag, format, ... ) ESP_EARLY_LOGV(tag, format, ##__VA_ARGS__) +#endif // BOOTLOADER_BUILD + +/** runtime macro to output logs at a specified level. + * + * @param tag tag of the log, which can be used to change the log level by ``esp_log_level_set`` at runtime. + * @param level level of the output log. + * @param format format of the output log. see ``printf`` + * @param ... variables to be replaced into the log. see ``printf`` + * + * @see ``printf`` + */ +#define ESP_LOG_LEVEL(level, tag, format, ...) do { \ + if (level==ESP_LOG_ERROR ) { esp_log_write(ESP_LOG_ERROR, tag, LOG_FORMAT(E, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ + else if (level==ESP_LOG_WARN ) { esp_log_write(ESP_LOG_WARN, tag, LOG_FORMAT(W, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ + else if (level==ESP_LOG_DEBUG ) { esp_log_write(ESP_LOG_DEBUG, tag, LOG_FORMAT(D, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ + else if (level==ESP_LOG_VERBOSE ) { esp_log_write(ESP_LOG_VERBOSE, tag, LOG_FORMAT(V, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ + else { esp_log_write(ESP_LOG_INFO, tag, LOG_FORMAT(I, format), esp_log_timestamp(), tag, ##__VA_ARGS__); } \ + } while(0) + +/** runtime macro to output logs at a specified level. Also check the level with ``LOG_LOCAL_LEVEL``. + * + * @see ``printf``, ``ESP_LOG_LEVEL`` + */ +#define ESP_LOG_LEVEL_LOCAL(level, tag, format, ...) do { \ + if ( LOG_LOCAL_LEVEL >= level ) ESP_LOG_LEVEL(level, tag, format, ##__VA_ARGS__); \ + } while(0) + +#ifdef __cplusplus +} +#endif + + +#endif /* __ESP_LOG_H__ */ diff --git a/components/log/include/esp_log_internal.h b/components/log/include/esp_log_internal.h new file mode 100644 index 00000000..94ec3463 --- /dev/null +++ b/components/log/include/esp_log_internal.h @@ -0,0 +1,24 @@ +// 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 __ESP_LOG_INTERNAL_H__ +#define __ESP_LOG_INTERNAL_H__ + +//these functions do not check level versus ESP_LOCAL_LEVEL, this should be done in esp_log.h +void esp_log_buffer_hex_internal(const char *tag, const void *buffer, uint16_t buff_len, esp_log_level_t level); +void esp_log_buffer_char_internal(const char *tag, const void *buffer, uint16_t buff_len, esp_log_level_t level); +void esp_log_buffer_hexdump_internal( const char *tag, const void *buffer, uint16_t buff_len, esp_log_level_t log_level); + +#endif + diff --git a/components/log/log.c b/components/log/log.c new file mode 100644 index 00000000..28bd89d8 --- /dev/null +++ b/components/log/log.c @@ -0,0 +1,467 @@ +// 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_level_set 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 +#include + +#include "esp_log.h" + +#include "rom/queue.h" +#include "soc/soc_memory_layout.h" + +//print number of bytes per line for esp_log_buffer_char and esp_log_buffer_hex +#define BYTES_PER_LINE 16 + +#ifndef BOOTLOADER_BUILD + +// 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; + uint32_t level : 3; + uint32_t generation : 29; +} cached_tag_entry_t; + +typedef struct uncached_tag_entry_{ + SLIST_ENTRY(uncached_tag_entry_) entries; + 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_log_default_level = ESP_LOG_VERBOSE; +static SLIST_HEAD(log_tags_head , uncached_tag_entry_) s_log_tags = SLIST_HEAD_INITIALIZER(s_log_tags); +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); +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(); + +vprintf_like_t esp_log_set_vprintf(vprintf_like_t func) +{ + if (!s_log_mutex) { + s_log_mutex = xSemaphoreCreateMutex(); + } + xSemaphoreTake(s_log_mutex, portMAX_DELAY); + + vprintf_like_t orig_func = s_log_print_func; + s_log_print_func = func; + + xSemaphoreGive(s_log_mutex); + return orig_func; +} + +void esp_log_level_set(const char* tag, esp_log_level_t level) +{ + if (!s_log_mutex) { + s_log_mutex = xSemaphoreCreateMutex(); + } + xSemaphoreTake(s_log_mutex, portMAX_DELAY); + + // for wildcard tag, remove all linked list items and clear the cache + if (strcmp(tag, "*") == 0) { + s_log_default_level = level; + clear_log_level_list(); + xSemaphoreGive(s_log_mutex); + return; + } + + //searching exist tag + uncached_tag_entry_t *it = NULL; + SLIST_FOREACH( it, &s_log_tags, entries ) { + if ( strcmp(it->tag, tag)==0 ) { + //one tag in the linked list match, update the level + it->level = level; + //quit with it != NULL + break; + } + } + //no exist tag, append new one + if ( it == NULL ) { + // allocate new linked list entry and append it to the head 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_log_mutex); + return; + } + new_entry->level = (uint8_t) level; + strcpy(new_entry->tag, tag); + SLIST_INSERT_HEAD( &s_log_tags, new_entry, entries ); + } + + //search in the cache and update it if exist + for (int 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 (strcmp(s_log_cache[i].tag,tag) == 0) { + s_log_cache[i].level = level; + break; + } + } + xSemaphoreGive(s_log_mutex); +} + +void clear_log_level_list() +{ + while( !SLIST_EMPTY(&s_log_tags)) { + SLIST_REMOVE_HEAD(&s_log_tags, entries ); + } + s_log_cache_entry_count = 0; + s_log_cache_max_generation = 0; +#ifdef LOG_BUILTIN_CHECKS + s_log_cache_misses = 0; +#endif +} + +void IRAM_ATTR esp_log_write(esp_log_level_t level, + const char* tag, + const char* format, ...) +{ + if (!s_log_mutex) { + s_log_mutex = xSemaphoreCreateMutex(); + } + 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_log_default_level; + } + add_to_cache(tag, level_for_tag); +#ifdef LOG_BUILTIN_CHECKS + ++s_log_cache_misses; +#endif + } + xSemaphoreGive(s_log_mutex); + if (!should_output(level, level_for_tag)) { + return; + } + + va_list list; + va_start(list, format); + (*s_log_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_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_log_cache_entry_count) { // Not found in cache + return false; + } + // Return level from cache + *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_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_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_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_log_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. + uncached_tag_entry_t *it; + SLIST_FOREACH( it, &s_log_tags, entries ) { + 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_log_cache[left_index].generation < s_log_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_log_cache[i]; + s_log_cache[i] = s_log_cache[j]; + s_log_cache[j] = tmp; +} +#endif //BOOTLOADER_BUILD + + +#ifndef BOOTLOADER_BUILD +#define ATTR IRAM_ATTR +#else +#define ATTR +#endif // BOOTLOADER_BUILD + +//the variable defined in ROM is the cpu frequency in MHz. +//as a workaround before the interface for this variable +extern uint32_t g_ticks_per_us_pro; + +uint32_t ATTR esp_log_early_timestamp() +{ + return xthal_get_ccount() / (g_ticks_per_us_pro * 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 && xPortGetCoreID() == 0) { + base = esp_log_early_timestamp(); + } + return base + xTaskGetTickCount() * (1000 / configTICK_RATE_HZ); +} + +#else + +uint32_t esp_log_timestamp() __attribute__((alias("esp_log_early_timestamp"))); + +#endif //BOOTLOADER_BUILD + +void esp_log_buffer_hex_internal(const char *tag, const void *buffer, uint16_t buff_len, + esp_log_level_t log_level) +{ + if ( buff_len == 0 ) return; + char temp_buffer[BYTES_PER_LINE+3]; //for not-byte-accessible memory + char hex_buffer[3*BYTES_PER_LINE+1]; + const char *ptr_line; + int bytes_cur_line; + + do { + if ( buff_len > BYTES_PER_LINE ) { + bytes_cur_line = BYTES_PER_LINE; + } else { + bytes_cur_line = buff_len; + } + if ( !esp_ptr_byte_accessible(buffer) ) { + //use memcpy to get around alignment issue + memcpy( temp_buffer, buffer, (bytes_cur_line+3)/4*4 ); + ptr_line = temp_buffer; + } else { + ptr_line = buffer; + } + + for( int i = 0; i < bytes_cur_line; i ++ ) { + sprintf( hex_buffer + 3*i, "%02x ", ptr_line[i] ); + } + ESP_LOG_LEVEL( log_level, tag, "%s", hex_buffer ); + buffer += bytes_cur_line; + buff_len -= bytes_cur_line; + } while( buff_len ); +} + +void esp_log_buffer_char_internal(const char *tag, const void *buffer, uint16_t buff_len, + esp_log_level_t log_level) +{ + if ( buff_len == 0 ) return; + char temp_buffer[BYTES_PER_LINE+3]; //for not-byte-accessible memory + char char_buffer[BYTES_PER_LINE+1]; + const char *ptr_line; + int bytes_cur_line; + + do { + if ( buff_len > BYTES_PER_LINE ) { + bytes_cur_line = BYTES_PER_LINE; + } else { + bytes_cur_line = buff_len; + } + if ( !esp_ptr_byte_accessible(buffer) ) { + //use memcpy to get around alignment issue + memcpy( temp_buffer, buffer, (bytes_cur_line+3)/4*4 ); + ptr_line = temp_buffer; + } else { + ptr_line = buffer; + } + + for( int i = 0; i < bytes_cur_line; i ++ ) { + sprintf( char_buffer + i, "%c", ptr_line[i] ); + } + ESP_LOG_LEVEL( log_level, tag, "%s", char_buffer ); + buffer += bytes_cur_line; + buff_len -= bytes_cur_line; + } while( buff_len ); +} + +void esp_log_buffer_hexdump_internal( const char *tag, const void *buffer, uint16_t buff_len, esp_log_level_t log_level) +{ + + if ( buff_len == 0 ) return; + char temp_buffer[BYTES_PER_LINE+3]; //for not-byte-accessible memory + const char *ptr_line; + //format: field[length] + // ADDR[10]+" "+DATA_HEX[8*3]+" "+DATA_HEX[8*3]+" |"+DATA_CHAR[8]+"|" + char hd_buffer[10+3+BYTES_PER_LINE*3+3+BYTES_PER_LINE+1+1]; + char *ptr_hd; + int bytes_cur_line; + + do { + if ( buff_len > BYTES_PER_LINE ) { + bytes_cur_line = BYTES_PER_LINE; + } else { + bytes_cur_line = buff_len; + } + if ( !esp_ptr_byte_accessible(buffer) ) { + //use memcpy to get around alignment issue + memcpy( temp_buffer, buffer, (bytes_cur_line+3)/4*4 ); + ptr_line = temp_buffer; + } else { + ptr_line = buffer; + } + ptr_hd = hd_buffer; + + ptr_hd += sprintf( ptr_hd, "%p ", buffer ); + for( int i = 0; i < BYTES_PER_LINE; i ++ ) { + if ( (i&7)==0 ) { + ptr_hd += sprintf( ptr_hd, " " ); + } + if ( i < bytes_cur_line ) { + ptr_hd += sprintf( ptr_hd, " %02x", ptr_line[i] ); + } else { + ptr_hd += sprintf( ptr_hd, " " ); + } + } + ptr_hd += sprintf( ptr_hd, " |" ); + for( int i = 0; i < bytes_cur_line; i ++ ) { + if ( isprint((int)ptr_line[i]) ) { + ptr_hd += sprintf( ptr_hd, "%c", ptr_line[i] ); + } else { + ptr_hd += sprintf( ptr_hd, "." ); + } + } + ptr_hd += sprintf( ptr_hd, "|" ); + + ESP_LOG_LEVEL( log_level, tag, "%s", hd_buffer ); + buffer += bytes_cur_line; + buff_len -= bytes_cur_line; + } while( buff_len ); +}