Beware that this post is related to an SDK in maintenance mode
More Info: Consider nRF Connect SDK for new designs
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

[bug] nrf_log_frontend: m_log_data.buffer overflow

Symptom

Depending on the data values written to the log this either triggers a hardfault or executes some random code with random results.

Repeatability

I can reproduce this by configuring deferred logging (NRF_LOG_DEFERRED = 1) and hammering on the log in the main loop:-

uint32_t loop_count = 0;
for (;;)
{

    char dummy[] = "XXXXXXXXXXXXXXXXXXXX";
    NRF_LOG_INFO("Main Loop %08X %s", loop_count++, NRF_LOG_PUSH(dummy));

    while (NRF_LOG_PROCESS()) {;}

}

This hardfaults after the same number of iterations every time. I have not calculated if this corresponds to the first or a subsequent wrap of the underlying buffer.

Analysis (so far)

The m_log_data.buffer can overflow by at least 4 bytes. This corrupts the adjacent m_log_data.timestamp_func pointer.

This pointer is de-referenced in nrf_log_frontend/std_header_set(). This is the source line:-

    m_log_data.buffer[(wr_idx + 2) & mask] = m_log_data.timestamp_func();

The NRF_LOG_PUSH() mechanism is strongly implicated because the overflowed data in the pointer is 0x58585858 ("XXXX").

I can dig deeper, but not just now.

SDK Version

nRF5_SDK_14.2.0_17b948a

Parents
  • New info:

    Using a watch point I have confirmed the overwrite occurs in the memcpy in nrf_log_push(). My suspicion is now with cont_buf_prealloc()...

    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);
            memcpy(p_dst_str, p_str, slen);  /*<<<< Buffer overflow here <<<<*/
        }
        return (uint32_t)p_dst_str;
    }

Reply
  • New info:

    Using a watch point I have confirmed the overwrite occurs in the memcpy in nrf_log_push(). My suspicion is now with cont_buf_prealloc()...

    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);
            memcpy(p_dst_str, p_str, slen);  /*<<<< Buffer overflow here <<<<*/
        }
        return (uint32_t)p_dst_str;
    }

Children
Related