NRF LOG crashlog backend

[abhipray]

I can't get flashlog/crashlog to work properly. The symptoms are that when NRF_LOG_BACKEND_FLASH_START_PAGE is set to 0 (i.e logs are written to address right after the application code ends), the flashlog status CLI command reveals that logs are being filled but flashlog read says the flashlog is empty.

If I clear the flashlog using flashlog clear command, I can start reading the newly written logs. However, when the NRF_LOG_FINAL_FLUSH is called before a reset, the code enters a hardfault condition. This means that the NRF_LOG_FINAL_FLUSH's writes are somehow corrupting flash.

To check for that, I changed NRF_LOG_BACKEND_FLASH_START_PAGE to a value after my application and before FDS pages (~150) and logging seems to be working fine and so does NRF_LOG_FINAL_FLUSH. Except when the flash is filled with logs-- when flashlog status says 99% of the flash is used, it doesn't increment the counter for dropped logs anymore. A reset after NRF_LOG_FINAL_FLUSH results in a hardfault again. 

Am I somehow misusing the module? I am using SDK 15.2 and FreeRTOS. I followed how the  flashlog module is used in the ble_cli_app example identically. 

 

[Susheel Nuguru]

Just a hunch but can you try to increase (maybe double) the below values in your FreeRTOSConfig.h file to see if that helps?

#define configMINIMAL_STACK_SIZE
#define configTOTAL_HEAP_SIZE

[abhipray]

Another bug I found was with nrf_log_backend_flash_init(). It appears that m_log_flash_fstorage evt_handler is not being set. Adding m_log_flash_fstorage.evt_handler = fstorage_evt_handler; fixes the issue where logs weren't being logged properly. 

Any reason why m_log_flash_fstorage might be reset to 0x00 on entry into the nrf_log_backend_flash_init() function even though it is being initialized in the NRF_FSTORAGE_DEF() declaration?

[Susheel Nuguru]

That is very strange. Which compiler are you using? looking at the code it does seem to do a memset on any structure which is related to this.

[abhipray]

I'm using arm-gcc. Turned out that there was an error in the linker script for the RAM section. I was not aligning one of the sections and variables were not ending up where they were supposed to, somehow corrupting the RAM. Patching the linker script fixed this particular issue where m_log_flash_fstorage was getting corrupted. 

Currently, everything looks good except for when I set the FLASH_START_PAGE to right after CODE_PAGE, then I can't read logs until I clear them. As a temporary patch, I set FLASH_START_PAGE to CODE_PAGE+1 which seems to work.

[Susheel Nuguru]

what is CODE_PAGE here?

[abhipray]

By CODE_PAGE I meant the flash page corresponding to CODE_END which is the macro for the address of the end of the code. 

[Susheel Nuguru]

You can use CODE_END as that does not guarantee that the page is empty to be used by log.

You always need assign FLASH_START_PAGE to CEIL the CODE_END using below

 (CODE_PAGE_SIZE*CEIL_DIV((uint32_t)CODE_END, CODE_PAGE_SIZE))

[abhipray]

Yes, I understand. What I meant was if I set NRF_LOG_BACKEND_FLASH_START_PAGE to 0, the default RUNTIME START_ADDR is set to the flash page right after CODE_PAGE. 
i.e #define RUNTIME_START_ADDR \
((NRF_LOG_BACKEND_FLASH_START_PAGE == 0) \
? (CODE_PAGE_SIZE * (CEIL_DIV((uint32_t)CODE_END, CODE_PAGE_SIZE))) \
: FLASH_LOG_START_ADDR)

However, this causes the problem where flashlog read does not present any logs even though flashlog status shows it's accumulating logs. Things only start working after flashlog clear.

Everything starts working normally if I change that line of code above to
#define RUNTIME_START_ADDR \
((NRF_LOG_BACKEND_FLASH_START_PAGE == 0) \
? (CODE_PAGE_SIZE * (CEIL_DIV((uint32_t)CODE_END, CODE_PAGE_SIZE) + 1)) \
: FLASH_LOG_START_ADDR)

[Susheel Nuguru]

I see, I am not able to replicate that problem, but I will report this to the team. Thanks for letting us know.