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

Confusing length handling in nrf_log_frontend.c

Hello,

I am talking about nRF5_SDK_17.0.2_d674dde/components/libraries/log/src/nrf_log_frontend.c.

In the case of HEXDUMP there seems to be some inconsistency in the packet length management as per header base.hexdump.len field.

If we Iook for all the occurrence of this information element, sometimes is it a 32bits word count, and sometimes it is an octet count.

  • in function invalid_packets_omit, @ line 332, we have this code : 

     *p_rd_idx += (HEADER_SIZE + p_header->base.hexdump.len);

so in this place, this is a uint32_t count.

  • in function log_skip, @line we have this code : 

    rd_idx += CEIL_DIV(header.base.hexdump.len, sizeof(uint32_t));

              so in this place this is an octet count.

  • In function nrf_log_frontend_hexdump, @line 688, we have : 

    p_header->base.hexdump.len = length;

    once again, an octet count.
  • In function nrf_log_frontend_dequeue, @lines 761-764, it is handled once again like an octet count.
  • In function buf_prealloc, @ line 490, it is handled like a uint32_t count. 

After thinking twice about all this, I understood that when in_progress flag is raised, this it is an uint32_t count, and otherwise an octet count.

I think that this aspect of the code is obscure and quite hard to understand / maintain. You should have made something like 

typedef struct
{
uint32_t in_progress : 1;
uint32_t allocated_len : 31;
} nrf_log_in_progress_header_t

typedef struct
{
uint32_t in_progress: 1;
uint32_t type : 2;
uint32_t data : 29;
} nrf_log_generic_header_t;

typedef struct
{
uint32_t in_progress: 1;
uint32_t type : 2;
uint32_t severity : 3;
uint32_t nargs : 4;
uint32_t addr : 22;
} nrf_log_std_header_t;

typedef struct
{
uint32_t in_progress: 1;
uint32_t type : 2;
uint32_t severity : 3;
uint32_t offset : 10;
uint32_t reserved : 6;
uint32_t len : 10;
} nrf_log_hexdump_header_t;

typedef union
{
nrf_log_in_progress_header_t in_progress;
nrf_log_generic_header_t generic;
nrf_log_std_header_t std;
nrf_log_hexdump_header_t hexdump;
uint32_t raw;
} nrf_log_main_header_t;

typedef struct
{
nrf_log_main_header_t base;
uint16_t module_id;
uint16_t dropped;
uint32_t timestamp;
} nrf_log_header_t;

And then whenever you have in_progress flag set to 1, use the in_progress union choice, and in_progress.allocated_len to get the length in terms of uint32_t word count. So in buf_prealloc and invalid_packets_omit you would just use in_progress union choice.

Or maybe I misunderstood what this code is doing, and then I would welcome your feedback on the above.

  • diff --git a/nrf-sdk/components/libraries/log/src/nrf_log_frontend.c b/nrf-sdk/components/libraries/log/src/nrf_log_frontend.c
    index ea962acb1..5e24dfab4 100644
    --- a/nrf-sdk/components/libraries/log/src/nrf_log_frontend.c
    +++ b/nrf-sdk/components/libraries/log/src/nrf_log_frontend.c
    @@ -317,17 +317,7 @@ static bool invalid_packets_omit(nrf_log_header_t const * p_header, uint32_t * p
         bool ret = false;
         if (p_header->base.generic.in_progress == 1)
         {
    -        switch (p_header->base.generic.type)
    -        {
    -        case HEADER_TYPE_STD:
    -            *p_rd_idx += (HEADER_SIZE + p_header->base.std.nargs);
    -            break;
    -        case HEADER_TYPE_HEXDUMP:
    -            *p_rd_idx += (HEADER_SIZE + p_header->base.hexdump.len);
    -            break;
    -        default:
    -            break;
    -        }
    +        *p_rd_idx += HEADER_SIZE + p_header->base.in_progress.allocated_len;
             ret = true;
         }
         return ret;
    @@ -424,12 +414,15 @@ static inline void std_header_set(uint32_t severity_mid,
             m_log_data.buffer[(wr_idx + 2) & mask] = m_log_data.timestamp_func();
         }
     
    +    nrf_log_main_header_t std_header = { .raw = 0 };
    +    std_header.std.severity    = severity_mid & NRF_LOG_LEVEL_MASK;
    +    std_header.std.nargs       = nargs;
    +    std_header.std.addr        = ((uint32_t)(p_str) & STD_ADDR_MASK);
    +    std_header.std.type        = HEADER_TYPE_STD;
    +    std_header.std.in_progress = 0;
    +
         nrf_log_header_t * p_header    = (nrf_log_header_t *)&m_log_data.buffer[wr_idx & mask];
    -    p_header->base.std.severity    = severity_mid & NRF_LOG_LEVEL_MASK;
    -    p_header->base.std.nargs       = nargs;
    -    p_header->base.std.addr        = ((uint32_t)(p_str) & STD_ADDR_MASK);
    -    p_header->base.std.type        = HEADER_TYPE_STD;
    -    p_header->base.std.in_progress = 0;
    +    p_header->base.raw = std_header.raw;
     }
     
     /**
    @@ -443,7 +436,7 @@ static inline void std_header_set(uint32_t severity_mid,
      * @return True if successful allocation, false otherwise.
      *
      */
    -static inline bool buf_prealloc(uint32_t content_len, uint32_t * p_wr_idx, bool std)
    +static inline bool buf_prealloc(uint32_t content_len, uint32_t * p_wr_idx)
     {
         uint32_t req_len = content_len + HEADER_SIZE;
         bool     ret            = true;
    @@ -471,18 +464,8 @@ static inline bool buf_prealloc(uint32_t content_len, uint32_t * p_wr_idx, bool
             nrf_log_main_header_t invalid_header;
             invalid_header.raw = 0;
     
    -        if (std)
    -        {
    -            invalid_header.std.type        = HEADER_TYPE_STD;
    -            invalid_header.std.in_progress = 1;
    -            invalid_header.std.nargs       = content_len;
    -        }
    -        else
    -        {
    -            invalid_header.hexdump.type = HEADER_TYPE_HEXDUMP;
    -            invalid_header.hexdump.in_progress = 1;
    -            invalid_header.hexdump.len = content_len;
    -        }
    +        invalid_header.in_progress.in_progress = 1;
    +        invalid_header.in_progress.allocated_len = content_len;
     
             nrf_log_main_header_t * p_header =
                        (nrf_log_main_header_t *)&m_log_data.buffer[m_log_data.wr_idx & m_log_data.mask];
    @@ -541,7 +524,7 @@ static inline void std_n(uint32_t           severity_mid,
         uint32_t mask   = m_log_data.mask;
         uint32_t wr_idx;
     
    -    if (buf_prealloc(nargs, &wr_idx, true))
    +    if (buf_prealloc(nargs, &wr_idx))
         {
             // Proceed only if buffer was successfully preallocated.
     
    @@ -642,7 +625,7 @@ void nrf_log_frontend_hexdump(uint32_t           severity_mid,
         uint32_t mask   = m_log_data.mask;
     
         uint32_t wr_idx;
    -    if (buf_prealloc(CEIL_DIV(length, sizeof(uint32_t)), &wr_idx, false))
    +    if (buf_prealloc(CEIL_DIV(length, sizeof(uint32_t)), &wr_idx))
         {
             uint32_t header_wr_idx = wr_idx;
             wr_idx += HEADER_SIZE;
    @@ -668,13 +651,15 @@ void nrf_log_frontend_hexdump(uint32_t           severity_mid,
             uint32_t dropped   = dropped_sat16_get();
             m_log_data.buffer[(header_wr_idx + 1) & mask] = module_id | (dropped << 16);
             //Header prepare
    -        nrf_log_header_t * p_header = (nrf_log_header_t *)&m_log_data.buffer[header_wr_idx & mask];
    -        p_header->base.hexdump.severity    = severity_mid & NRF_LOG_LEVEL_MASK;
    -        p_header->base.hexdump.offset      = 0;
    -        p_header->base.hexdump.len         = length;
    -        p_header->base.hexdump.type        = HEADER_TYPE_HEXDUMP;
    -        p_header->base.hexdump.in_progress = 0;
    +        nrf_log_main_header_t hexdump_header = { .raw = 0 };
    +        hexdump_header.hexdump.severity    = severity_mid & NRF_LOG_LEVEL_MASK;
    +        hexdump_header.hexdump.offset      = 0;
    +        hexdump_header.hexdump.len         = length;
    +        hexdump_header.hexdump.type        = HEADER_TYPE_HEXDUMP;
    +        hexdump_header.hexdump.in_progress = 0;
     
    +        nrf_log_header_t * p_header = (nrf_log_header_t *)&m_log_data.buffer[header_wr_idx & mask];
    +        p_header->base.raw = hexdump_header.raw;
     
     
         }
    diff --git a/nrf-sdk/components/libraries/log/src/nrf_log_internal.h b/nrf-sdk/components/libraries/log/src/nrf_log_internal.h
    index d71680b20..e1a03952c 100644
    --- a/nrf-sdk/components/libraries/log/src/nrf_log_internal.h
    +++ b/nrf-sdk/components/libraries/log/src/nrf_log_internal.h
    @@ -362,15 +362,21 @@ extern _CONST nrf_log_module_const_data_t NRF_LOG_ITEM_DATA_CONST(NRF_LOG_MODULE
     
     typedef struct
     {
    -    uint32_t type       : 2;
    +    uint32_t in_progress  : 1;
    +    uint32_t allocated_len: 31;
    +} nrf_log_in_progress_header_t;
    +
    +typedef struct
    +{
         uint32_t in_progress: 1;
    +    uint32_t type       : 2;
         uint32_t data       : 29;
     } nrf_log_generic_header_t;
     
     typedef struct
     {
    -    uint32_t type       : 2;
         uint32_t in_progress: 1;
    +    uint32_t type       : 2;
         uint32_t severity   : 3;
         uint32_t nargs      : 4;
         uint32_t addr       : 22;
    @@ -378,8 +384,8 @@ typedef struct
     
     typedef struct
     {
    -    uint32_t type       : 2;
         uint32_t in_progress: 1;
    +    uint32_t type       : 2;
         uint32_t severity   : 3;
         uint32_t offset     : 10;
         uint32_t reserved   : 6;
    @@ -388,10 +394,11 @@ typedef struct
     
     typedef union
     {
    -    nrf_log_generic_header_t generic;
    -    nrf_log_std_header_t     std;
    -    nrf_log_hexdump_header_t hexdump;
    -    uint32_t                 raw;
    +    nrf_log_in_progress_header_t in_progress;
    +    nrf_log_generic_header_t     generic;
    +    nrf_log_std_header_t         std;
    +    nrf_log_hexdump_header_t     hexdump;
    +    uint32_t                     raw;
     } nrf_log_main_header_t;
     
     typedef struct
    

    To be a little more specific I attached a patch file.

  • Hi,

    Than you for posting your suggestions. I confirmed with the developers that they agree that this will make the code more readable.

    I have created an internal report, it will be considered for future releases.

    Best regards,
    Jørgen

  • FYI, the reason why I had to look into this code is because I am currently investigating some bug, and one of the symptom is logging not working as expected in some circumstances.


    Concerning my comment, that was not only a matter of code clarity. If you have code like this : 

    nrf_log_header_t * p_header = (nrf_log_header_t *)&m_log_data.buffer[header_wr_idx & mask];
    p_header->base.hexdump.severity = severity_mid & NRF_LOG_LEVEL_MASK;
    p_header->base.hexdump.offset = 0;
    p_header->base.hexdump.len = length;
    p_header->base.hexdump.type = HEADER_TYPE_HEXDUMP;
    p_header->base.hexdump.in_progress = 0;

    Then you rely on the compiler to make the p_header->base.raw word written as an atomic 32bit operation into the circular buffer, which is desirable, as the writing may occur in a different task than the flushing when logging is differed.

    I think that there is no problem with the current code (because the compiler will probably optimise all the field accesses in register only operation before push all fields in a single 32bit word to the memory), however, even though the in_progress field is set last, such kind of coding, relying on the compiler goodness, is per se problematic : that is why I made this patch, so as to be 200% that the issue is on our side.

  • I understand your concern and have added your comment to the internal report.

Related