OVMS3-idf/components/log/log.c

// 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 <freertos/FreeRTOS.h>
#include <freertos/FreeRTOSConfig.h>
#include <freertos/task.h>
#include <freertos/timers.h>
#include <freertos/semphr.h>
#endif

#include "esp_attr.h"
#include "xtensa/hal.h"
#include "soc/soc.h"
#include <stdbool.h>
#include <stdarg.h>
#include <string.h>
#include <stdlib.h>
#include <stdio.h>
#include <assert.h>
#include <ctype.h>

#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 ( configUSE_TIMERS == 1 ) && ( INCLUDE_xTimerGetTimerDaemonTaskHandle == 0 )
    #warning "Logging from timer context may block, consider enabling INCLUDE_xTimerGetTimerDaemonTaskHandle"
#elif ( configUSE_TIMERS == 1 ) && ( INCLUDE_xTimerGetTimerDaemonTaskHandle == 1 )
    // Avoid blocking in timer context:
    if (xTaskGetSchedulerState() != taskSCHEDULER_RUNNING
            || xTaskGetCurrentTaskHandle() == xTimerGetTimerDaemonTaskHandle()) {
        if (xSemaphoreTake(s_log_mutex, 0) == pdFALSE) {
            return;
        }
    }
    else
#endif
    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 );
}