NRF_LOG_HEXDUMP_* raises Data Access Violation Fault if a large buffer is used

[martinspedro]

Hi to all,

I have found that using SDK17.0.0 on NRF52832, whenever I try to use NRF_LOG_HEXDUMP_DEBUG for a large buffer (more than a 1000 elements), I get a Data Access Violation Fault.

I understand that since the NRF_LOG is deferred and my buffer is allocated in stack, I can get the buffer pointer to be corrupted. 
Aware of that, after calling the NRF_LOG_HEXDUMP_DEBUG I call the NRF_LOG_FINAL_FLUSH, in order to fully flush the logs.
I have also changed the NRF_LOG_BUFSIZE to 4096, in order to fully store my buffer (1800 bytes)

I have also noticed that the output of my calls to NRF_LOG_HEXDUMP_DEBUG are capped at 80 bytes (8 columns x 10 rows), even if the buffer contains more data and and the length argument of the NRF_LOG_HEXDUMP_DEBUG call is more than 80 bytes.

Below is a code snippet. I have tried to dump the buffer immediately after creation (even if it is all zeroes), just to remove the possibility of errors in functions that manipulate the buffer contents. Still getting Data Access Violation Fault.

uint8_t cert_buffer[1800] = {0};
NRF_LOG_HEXDUMP_INFO(cert_buffer, 1800);
NRF_LOG_FINAL_FLUSH();

Am I missing something or is this a bug? Can anyone reproduce this behavior?

Thanks in advance,

Pedro

[ovrebekk]

Hi

Each byte of RAW data is converted to an ASCII hex presentation, so essentially each byte of raw data becomes multiple bytes of log data. 

Does it work if you try to send a shorter dump, such as 500 bytes?

Best regards
Torbjørn

[martinspedro]

Hi ovrebekk,

I took the conversion from hex to ASCII in consideration. Since I couldn't pinpoint if that conversion was done when storing or printing the data, I made the NRF_LOG buffer bigger than required. From hex to ASCII, you double the amount of bytes required to store a character, so 2*1800 < 4096, which means that the full buffer should fit inside NRF_LOG buffer.

Note that the max amount of data printed is always capped at 80 bytes of hexadecimal data.

ovrebekk said:

Does it work if you try to send a shorter dump, such as 500 bytes?

It doesn't raises a Data Access Violation Fault, but data is still capped at 80 hex bytes

[ovrebekk]

Hi 

Are you able to share your sdk_config.h file?

I got some help from one of the developers, and he was able to print buffers longer than 80 bytes. 

For the data access violation fault, have you tried to increase the size of the call stack?

Best regards
Torbjørn

[martinspedro]

Hi,

Sharing the sdk_config.h and the app_config.h (I define the USE_APP_CONFIG in my Makefile).

From your answer, I believe that one thing might not be clear: I have no data access violation fault when I manipulate the buffer (for instance, R/W operations and passing it as an argument to other functions). Only when calling the NRF_LOG_HEXDUMP_* I have a data access violation fault.

I have tried increasing the call stack (already at 8192), but no differences.

ovrebekk said:

I got some help from one of the developers, and he was able to print buffers longer than 80 bytes.

Thank you for testing. I believe the 80 chars "limit" might be a problem in my configs.
Nevertheless, was the developer able to reproduce the data access violation fault?

app_config.h1715.sdk_config.h

Best regards,

Pedro

[ovrebekk]

Hi Pedro

Yes, the developer was able to reproduce the stack overflow issue as well, when using an 1800 byte buffer. 

Thanks for sharing the config files, I have shared them with the developer and will get back to you. 

Best regards
Torbjørn

[martinspedro]

Thank you for the quick response, ovrebekk.

Please ping me when you have news.

Best regards,

Pedro

[ovrebekk]

Hi Pedro

He did some experiments trying to increase the NRF_LOG_MSGPOOL_ELEMENT_COUNT parameter in sdk_config.h. 

First he tested with 40 which seemed to work fine, but increasing it much beyond this didn't seem to provide stable results. 

In order to print 1800 bytes you would need to set this parameter to 90, but this doesn't seem to work properly, there is still some other limit somewhere preventing all the bytes from being written. 

Could you try to change this value as well and see how it affect the output?

Best regards
Torbjørn

[martinspedro]

Hi @ovrebekk,

Some updates from my side.
I have created a simple project which uses the sdk_configs.h I shared. It has a main loop that only dumps the buffer. The buffer is still being declared inside main, so, its allocated on the stack, as in the previous tests.

ovrebekk said:

Could you try to change this value as well and see how it affect the output?

I have tried with different values of NRF_LOG_MSGPOOL_ELEMENT_COUNT. Below is a summary

NRF_LOG_MSGPOOL_ELEMENT_COUNT	Bytes printed	Error received
8	80	Non-Maskable Interrupt
16	104	Non-Maskable Interrupt.
32	208	Data Access Violation escalates to Hard Fault
40	280	Data Access Violation escalates to Hard Fault
64	384	Data Access Violation escalates to Hard Fault
90	512	Data Access Violation escalates to Hard Fault
128	464	Data Access Violation escalates to Hard Fault

A screenshot of the call stack in one of the cases:

Also, during my tests, I noticed that the Data Access Violation occurs because, somehow, the flushing of the logs attempts to access addresses that are impossible, like 0x616E696D (value when NRF_LOG_MSGPOOL_ELEMENT_COUNT = 128).

ovrebekk said:

In order to print 1800 bytes you would need to set this parameter to 90, but this doesn't seem to work properly, there is still some other limit somewhere preventing all the bytes from being written

I couldn't duplicate. My tests always cause some erroneous condition that prevents me from printing the buffer.

Can you please analyze the data above? I think I narrowed it down to the flushing of the logs, but I am not sure yet if the problem resides on the NRF_LOG module or the backend module the NRF_LOG uses to flush the logs...

[ovrebekk]

Hi 

The developer found a workaround by writing the data in smaller chunks, and flushing the buffers in between. 

He used the following configuration:

NRF_LOG_MSGPOOL_ELEMENT_SIZE 20
NRF_LOG_MSGPOOL_ELEMENT_COUNT 110
NRF_LOG_BUFSIZE 4096

and then he wrote the buffer like this:

uint8_t cert_buffer[1800] = {0};                                                                                                   
for (int i = 0; i < 1800; i += 600)                                                                                                
{                                                                                                                                  
    NRF_LOG_HEXDUMP_INFO(cert_buffer + i, 600);                                                                                    
    NRF_LOG_FLUSH();                                                                                                               
}

Can you give this a go and see if it works better?

It's also important to note that the NRF_LOG_FINAL_FLUSH() function should not be used in normal operation. This one is only meant to be used inside error handlers (running in interrupt context). Please use NRF_LOG_FLUSH() instead. 

Best regards
Torbjørn

[martinspedro]

Hi ovrebekk,

ovrebekk said:

Can you give this a go and see if it works better?

It works better. I am able to print 135 lines, with 8 bytes each. So I get 1080 bytes from the 1800 bytes.

Please note one thing. I am aware that I can create workarounds to fully print the entire certificate (1800 bytes), by printing it in steps or by dumping the variable contents to file through a debugger.

On this issue I would like the discussion not be focused on getting workaround. Instead, I would prefer to address these two things:
1. Why NRF_LOG_HEXDUMP_* prints less bytes than requested and does not output any error messages
2. Why, when an error message is received, is a hardly recoverable Data Access Violation. Are there no verification steps inside NRF_LOG_HEXDUMP_* ?

To my awareness, there are also no documented size limitations of the NRF_LOG_HEXDUMP_*.

Can you please address the two topics above? If you need more debug data/help from my side, please advice.

[ovrebekk]

Hi

I agree it would be nice to know the reason for these issues, and what exactly sets the limits. 

I tried to do some testing on my own and found I was able to print up to 800 bytes in one chunk, but 1024 bytes or more would fail. 

I need some more time to look properly into this though. I need some assistance from the original developer of the logging libraries, and he is not available until next week. 

Best regards
Torbjørn

[martinspedro]

Hi ovrebekk,

Sure, take your time to fully analyse this issue.
As you pointed above, there are workarounds that work just fine, which I am using on the meantime.

Once you have any news and/or require inputs from my side, just let me know. Happy to help.

Best regards,
Pedro