[bugreport] nrf_log deferred mode hardfaults

[Keton]

Hi,

I think I've found reliable way to cause hardfault when executing nrf_log_frontend-dequeue() and most likely cause nrf_log modules to write outside of allocated buffer space while in deferred mode.

It happens on (at least) SDK13.1.0 with S132 4.0.2 and 4.0.4 compiled on Keil 5.23. I'm using custom nRF52832 board with J-Link OB but this can be also reproduced on nRF52-DK.

Attached please find minimal test example ble_app_crash.zip

It's ble_app_template with scheduler and deferred RTT logging enabled. To cause reliable hardfaults sdk_config.h included in the project should be used as the code stability depends on sizes of RTT buffers.

Crashing code is as follows:

//playing around with LOG_COUNTER_MAX results in code crashing or not
//31 --> initial crash
//1-24; 48-75 --> ok; 
//25-47; 76 --> crash
#define LOG_COUNTER_MAX 31

static void log_fill_crash(void)
{
	for(uint8_t i=0; i<LOG_COUNTER_MAX; i++) 
    {
        static char buff[33];
		memset(buff,0,sizeof(buff));
		
		snprintf(buff,sizeof(buff),"X:0.12345 Y:-0.12345 Z:1.23456");
        NRF_LOG_RAW_INFO("%s\r\n",nrf_log_push(buff));
		
    }
}

Calling log_fill_crash() just before infinite loop in main() causes a hardfault as soon as NRF_LOG_PROCESS() is executed.

Changing LOG_COUNTER_MAX value results in different program behaviors. For 1-24 log output is correctly truncated, 25-47 gives a hardfault with varying amount of gibberish printed out. At least some of the values in 48-75 range result in correct behavior but 76 causes crash.

Could you please check if this is indeed a bug or maybe I'm just doing something wrong in my project setup?

[Jakub Rzeszutko]

Hi,

Thank you for reporting the issue. We will check it shortly.

[Daniel Berton]

I have also been able to replicate this problem in my own code. I am using SDK v14.1.0

I believe I have been able to isolate the cause of this hardfault to the frontend log buffer overflowing due to a memcpy overwriting m_log_data.p_backend_head.

below function is where m_log_data.p_backend_head gets overwritten

uint32_t nrf_log_push(char * const p_str)
{
    if ((m_log_data.autoflush) || (p_str == NULL))
    {
        return (uint32_t)p_str;
    }

    uint32_t mask      = m_log_data.mask;
    uint32_t slen      = strlen(p_str) + 1;
    uint32_t buflen    = CEIL_DIV(slen, sizeof(uint32_t));
    uint32_t offset    = 0;
    uint32_t wr_idx;
    char   * p_dst_str = (char *)cont_buf_prealloc(buflen, &offset, &wr_idx);
    if (p_dst_str)
    {
        nrf_log_header_t * p_header = (nrf_log_header_t *)&m_log_data.buffer[wr_idx & mask];
        PUSHED_HEADER_FILL(p_header, offset, buflen);

        // when cont_buf_prealloc() returns a buffer that requires a wrap-around of the
	// frontend log queue (as it is a circular buffer). memcpy() then treats
	// the returned buffer as contiguous and overwrites memory past the end of the buffer.
	// which, with a long enough string will overwrite the backend buffer pointer    
    // m_log_data.p_backend_head )
	memcpy(p_dst_str, p_str, slen);
    }
    return (uint32_t)p_dst_str;
}

a workaround is to replace the memcpy with a for loop that checks for overflow (code below), however it seems this results in truncated log strings being output. At least it no longer hardfaults though.

uint32_t nrf_log_push(char * const p_str)
{
    if ((m_log_data.autoflush) || (p_str == NULL))
    {
        return (uint32_t)p_str;
    }

    uint32_t mask      = m_log_data.mask;
    uint32_t slen      = strlen(p_str) + 1;
    uint32_t buflen    = CEIL_DIV(slen, sizeof(uint32_t));
    uint32_t offset    = 0;
    uint32_t wr_idx;
    char   * p_dst_str = (char *)cont_buf_prealloc(buflen, &offset, &wr_idx);
    char   * p_dst_str_start = p_dst_str;
    if (p_dst_str)
    {
        nrf_log_header_t * p_header = (nrf_log_header_t *)&m_log_data.buffer[wr_idx & mask];
        PUSHED_HEADER_FILL(p_header, offset, buflen);
        for(int i = 0; i < slen; i++ ){
            // check for buffer overflow
            if(p_dst_str >= (char *) &m_log_data.buffer[NRF_LOG_BUF_WORDS]){
                p_dst_str = (char *) &m_log_data.buffer[0];
            }
            
            *p_dst_str = p_str[i] ;
            p_dst_str ++;
        }
    }
    return (uint32_t)p_dst_str_start;
}

My testing main function is Below.

#include <stdio.h>
#include <stdint.h>
#include "nrf_delay.h"
#include "app_error.h"
#include "nrf_assert.h"


#include "nrf_log.h"
#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"



/** @brief Function for main application entry.
 */
int main(void)
{
    uint32_t err_code;
    static char test_str[] = "TESTING, TESTING,SHOULD NOT HARDFAULT";
    err_code = NRF_LOG_INIT(NULL);
    APP_ERROR_CHECK(err_code);

    NRF_LOG_DEFAULT_BACKENDS_INIT();

    while (true)
    {
        NRF_LOG_INFO("%s",nrf_log_push(test_str));
        NRF_LOG_FLUSH();
        nrf_delay_ms(10);
    }
}

The relevent section of sdk_config.h is below

// </h> 
//==========================================================

// <h> nRF_Log 

//==========================================================
// <e> NRF_LOG_BACKEND_RTT_ENABLED - nrf_log_backend_rtt - Log RTT backend
//==========================================================
#ifndef NRF_LOG_BACKEND_RTT_ENABLED
#define NRF_LOG_BACKEND_RTT_ENABLED 1
#endif
// <o> NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE - Size of buffer for partially processed strings. 
// <i> Size of the buffer is a trade-off between RAM usage and processing.
// <i> if buffer is smaller then strings will often be fragmented.
// <i> It is recommended to use size which will fit typical log and only the
// <i> longer one will be fragmented.

#ifndef NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE
#define NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE 64
#endif

// </e>

// <e> NRF_LOG_BACKEND_UART_ENABLED - nrf_log_backend_uart - Log UART backend
//==========================================================
#ifndef NRF_LOG_BACKEND_UART_ENABLED
#define NRF_LOG_BACKEND_UART_ENABLED 0
#endif
// <o> NRF_LOG_BACKEND_UART_TX_PIN - UART TX pin 
#ifndef NRF_LOG_BACKEND_UART_TX_PIN
#define NRF_LOG_BACKEND_UART_TX_PIN 6
#endif

// <o> NRF_LOG_BACKEND_UART_BAUDRATE  - Default Baudrate
 
// <323584=> 1200 baud 
// <643072=> 2400 baud 
// <1290240=> 4800 baud 
// <2576384=> 9600 baud 
// <3862528=> 14400 baud 
// <5152768=> 19200 baud 
// <7716864=> 28800 baud 
// <10289152=> 38400 baud 
// <15400960=> 57600 baud 
// <20615168=> 76800 baud 
// <30801920=> 115200 baud 
// <61865984=> 230400 baud 
// <67108864=> 250000 baud 
// <121634816=> 460800 baud 
// <251658240=> 921600 baud 
// <268435456=> 1000000 baud 

#ifndef NRF_LOG_BACKEND_UART_BAUDRATE
#define NRF_LOG_BACKEND_UART_BAUDRATE 30801920
#endif

// <o> NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE - Size of buffer for partially processed strings. 
// <i> Size of the buffer is a trade-off between RAM usage and processing.
// <i> if buffer is smaller then strings will often be fragmented.
// <i> It is recommended to use size which will fit typical log and only the
// <i> longer one will be fragmented.

#ifndef NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE
#define NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE 64
#endif

// </e>

// <h> nrf_log - Logger

//==========================================================
// <e> NRF_LOG_ENABLED - Logging module for nRF5 SDK
//==========================================================
#ifndef NRF_LOG_ENABLED
#define NRF_LOG_ENABLED 1
#endif
// <e> NRF_LOG_USES_COLORS - If enabled then ANSI escape code for colors is prefixed to every string
//==========================================================
#ifndef NRF_LOG_USES_COLORS
#define NRF_LOG_USES_COLORS 0
#endif
// <o> NRF_LOG_COLOR_DEFAULT  - ANSI escape code prefix.
 
// <0=> Default 
// <1=> Black 
// <2=> Red 
// <3=> Green 
// <4=> Yellow 
// <5=> Blue 
// <6=> Magenta 
// <7=> Cyan 
// <8=> White 

#ifndef NRF_LOG_COLOR_DEFAULT
#define NRF_LOG_COLOR_DEFAULT 0
#endif

// <o> NRF_LOG_ERROR_COLOR  - ANSI escape code prefix.
 
// <0=> Default 
// <1=> Black 
// <2=> Red 
// <3=> Green 
// <4=> Yellow 
// <5=> Blue 
// <6=> Magenta 
// <7=> Cyan 
// <8=> White 

#ifndef NRF_LOG_ERROR_COLOR
#define NRF_LOG_ERROR_COLOR 2
#endif

// <o> NRF_LOG_WARNING_COLOR  - ANSI escape code prefix.
 
// <0=> Default 
// <1=> Black 
// <2=> Red 
// <3=> Green 
// <4=> Yellow 
// <5=> Blue 
// <6=> Magenta 
// <7=> Cyan 
// <8=> White 

#ifndef NRF_LOG_WARNING_COLOR
#define NRF_LOG_WARNING_COLOR 4
#endif

// </e>

// <o> NRF_LOG_DEFAULT_LEVEL  - Default Severity level
 
// <0=> Off 
// <1=> Error 
// <2=> Warning 
// <3=> Info 
// <4=> Debug 

#ifndef NRF_LOG_DEFAULT_LEVEL
#define NRF_LOG_DEFAULT_LEVEL 3
#endif

// <q> NRF_LOG_DEFERRED  - Enable deffered logger.
 

// <i> Log data is buffered and can be processed in idle.

#ifndef NRF_LOG_DEFERRED
#define NRF_LOG_DEFERRED 1
#endif

// <o> NRF_LOG_BUFSIZE  - Size of the buffer for storing logs (in bytes).
 

// <i> Must be power of 2 and multiple of 4.
// <i> If NRF_LOG_DEFERRED = 0 then buffer size can be reduced to minimum.
// <128=> 128 
// <256=> 256 
// <512=> 512 
// <1024=> 1024 
// <2048=> 2048 
// <4096=> 4096 
// <8192=> 8192 
// <16384=> 16384 

#ifndef NRF_LOG_BUFSIZE
#define NRF_LOG_BUFSIZE 1024
#endif

// <q> NRF_LOG_ALLOW_OVERFLOW  - Configures behavior when circular buffer is full.
 

// <i> If set then oldest logs are overwritten. Otherwise a 
// <i> marker is injected informing about overflow.

#ifndef NRF_LOG_ALLOW_OVERFLOW
#define NRF_LOG_ALLOW_OVERFLOW 1
#endif

// <q> NRF_LOG_USES_TIMESTAMP  - Enable timestamping
 

// <i> Function for getting the timestamp is provided by the user

#ifndef NRF_LOG_USES_TIMESTAMP
#define NRF_LOG_USES_TIMESTAMP 0
#endif

// <q> NRF_LOG_FILTERS_ENABLED  - Enable dynamic filtering of logs.
 

#ifndef NRF_LOG_FILTERS_ENABLED
#define NRF_LOG_FILTERS_ENABLED 0
#endif

// <q> NRF_LOG_CLI_CMDS  - Enable CLI commands for the module.
 

#ifndef NRF_LOG_CLI_CMDS
#define NRF_LOG_CLI_CMDS 0
#endif

// <h> Log message pool - Configuration of log message pool

//==========================================================
// <o> NRF_LOG_MSGPOOL_ELEMENT_SIZE - Size of a single element in the pool of memory objects. 
// <i> If a small value is set, then performance of logs processing
// <i> is degraded because data is fragmented. Bigger value impacts
// <i> RAM memory utilization. The size is set to fit a message with
// <i> a timestamp and up to 2 arguments in a single memory object.

#ifndef NRF_LOG_MSGPOOL_ELEMENT_SIZE
#define NRF_LOG_MSGPOOL_ELEMENT_SIZE 20
#endif

// <o> NRF_LOG_MSGPOOL_ELEMENT_COUNT - Number of elements in the pool of memory objects 
// <i> If a small value is set, then it may lead to a deadlock
// <i> in certain cases if backend has high latency and holds
// <i> multiple messages for long time. Bigger value impacts
// <i> RAM memory usage.

#ifndef NRF_LOG_MSGPOOL_ELEMENT_COUNT
#define NRF_LOG_MSGPOOL_ELEMENT_COUNT 8
#endif

[Keton]

this has been resolved by patching cont_buff_prealloc() take look at my other question here: devzone.nordicsemi.com/.../