nrf_log fixes in SDK14.1.0

[Keton]

I've noticed following line in SDK14.1 release notes:

`

• Fixed a bug where nrf_log could crash when heavily loaded. `

I'm using SDK13.1 in my current project and I'm experiencing nrf_log related crashes under load as described here.

Please elaborate on what exactly was fixed and if it's related to problems I'm experiencing. Also if possible please provide some pointers on how to backport this fix into SDK13.1. Unfortunately I can't upgrade to SDK14.1 at this time.

[Krzysztof Chruscinski]

Hi,

you can try to find function cont_buf_prealloc in nrf_log_frontend.c and update following code:

uint32_t available_words = (m_log_data.mask + 1) -
                           (m_log_data.wr_idx & m_log_data.mask);

should be changed to:

uint32_t available_words = (m_log_data.mask + 1) -
                            (m_log_data.wr_idx - m_log_data.rd_idx);

That should help.

UPDATE Actually, the fix provided was not good and there was still a bug in SDK 14.2.0 in that function. Here is the updated version the function:

static inline uint32_t * cont_buf_prealloc(uint32_t len32,
                                       uint32_t * p_offset,
                                       uint32_t * p_wr_idx){
uint32_t * p_buf = NULL;

len32 += PUSHED_HEADER_SIZE; // Increment because 32bit header is needed to be stored.

CRITICAL_REGION_ENTER();
*p_wr_idx = m_log_data.wr_idx;
uint32_t available_words = (m_log_data.mask + 1) -
                            (m_log_data.wr_idx - m_log_data.rd_idx);
uint32_t cont_words =  (m_log_data.mask + 1) - (m_log_data.wr_idx & m_log_data.mask);

//available space is continuous
uint32_t curr_pos_available = (available_words <= cont_words) ? available_words : cont_words;
uint32_t start_pos_available = (available_words <= cont_words) ? 0 : (available_words - cont_words);
if (len32 <= curr_pos_available)
{
    // buffer will fit as is
    p_buf              = &m_log_data.buffer[(m_log_data.wr_idx + 1) & m_log_data.mask];
    m_log_data.wr_idx += len32;
    *p_offset          = 0;
}
else if (len32 <= start_pos_available)
{
    // wraping to the begining of the buffer
    m_log_data.wr_idx += (len32 + cont_words);
    *p_offset          = cont_words;
    p_buf              = m_log_data.buffer;
}

CRITICAL_REGION_EXIT();

return p_buf;}

[Keton]

thanks, it solved the problem for test case I've linked but still I'm able to crash MCU by doing bunch of: NRF_LOG_RAW_DEBUG("%s\r\n",nrf_log_push(str)); where str is: char str[150]. When I'm using SEGGER_RTT_Write instead of nrf_log it doesn't crash so it's most likely another memory access issue in nrf_log.

[Keton]

Any updates on this? I have a project where I have to use deffered logging due to timing constraints and NRF_LOG hardfaults every time.

[Keton]

It seems that fix posted above is only valid when NRF_LOG_DEFERRED_BUFSIZE is smaller than logged data amount. For large NRF_LOG_DEFERRED_BUFSIZE patch above leads to a hardfault while original buffer size estimate works.

I know that Nordic devs are busy preparing SDK15 release but for all users like me who are stuck with SDK13 I'd really appreciate that someone who knows internals of nrf_log module takes a look if this approach is correct.

diff --git a/components/libraries/log/src/nrf_log_frontend.c b/components/libraries/log/src/nrf_log_frontend.c
index e8f80c10..e6f5dfd7 100644
--- a/components/libraries/log/src/nrf_log_frontend.c
+++ b/components/libraries/log/src/nrf_log_frontend.c
@@ -379,8 +379,25 @@ static inline uint32_t * cont_buf_prealloc(uint32_t len32,

     CRITICAL_REGION_ENTER();
     *p_wr_idx = m_log_data.wr_idx;
+
     uint32_t available_words = (m_log_data.mask + 1) -
                                (m_log_data.wr_idx & m_log_data.mask);
+
+       /*
+               This is more robust attempt of fixing NRF_LOG_DEFFERED=1 hardfault.
+               Nordic posted fix here: devzone.nordicsemi.com/.../
+               The change works only when NRF_LOG_DEFERRED_BUFSIZE isn't large enough to fit all log data before log processing happens.
+               When NRF_LOG_DEFERRED_BUFSIZE is large i.e. 4096 words proposed fix leads to hardfault by overflowing subtraction result
+
+               This is an attempt of more robust fix which assumes that smaller free space estimate is correct.
+       */
+
+       //this is how Nordic proposes to fix it
+       uint32_t available_words_alt=(m_log_data.mask + 1) - (m_log_data.wr_idx - m_log_data.rd_idx);
+
+       //assume that smaller value is correct
+       if(available_words_alt<available_words) available_words=available_words_alt;
+
     if (len32 <= available_words)
     {
         // buffer will fit as is
--

[Krzysztof Chruscinski]

Hi,

we have made significant changes in nrf_log in SDK 14.0 and then bunch of stability fixes in SDK 14.1 It is hard to provide the patch for them. You can try to port latest nrf_log to SDK 13. Here is the migration guide which might be helpful: