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...