Implement flashlog backend

[corentind]

Hello,

I am working on an nRF52840 with S140SD chip.

I am currently using the RTT as a backend for logs. I tried adding the Flashlog backend in order to save the logs in non-volatile memory however it doesn't appear to be saving them in the flash.

Here is my current initialization:

// Define log backend for using non-volatile memory
NRF_LOG_BACKEND_FLASHLOG_DEF(m_flash_log_backend);
NRF_LOG_BACKEND_CRASHLOG_DEF(m_crash_log_backend);

void log_init() {
  // Initialize logging module
  ret_code_t err_code = NRF_LOG_INIT(app_timer_cnt_get, TIMESTAMP_FREQ);
  APP_ERROR_CHECK(err_code);
  NRF_LOG_DEFAULT_BACKENDS_INIT(); // Enable RTT

  // Add flashlog backend
  flashlog_init();

  NRF_LOG_ERROR("Test flash log");
  NRF_LOG_WARNING("Test warning flash log");
  NRF_LOG_INFO("Test info flash log");
  NRF_LOG_FLUSH();
}

void flashlog_init(void)
{
    ret_code_t ret;
    int32_t backend_id;

    ret = nrf_log_backend_flash_init(&nrf_fstorage_sd);
    APP_ERROR_CHECK(ret);

    backend_id = nrf_log_backend_add(&m_flash_log_backend, NRF_LOG_SEVERITY_WARNING);
    APP_ERROR_CHECK_BOOL(backend_id >= 0);

    backend_id = nrf_log_backend_add(&m_crash_log_backend, NRF_LOG_SEVERITY_INFO);
    APP_ERROR_CHECK_BOOL(backend_id >= 0);

    nrf_log_backend_enable(&m_flash_log_backend);
    nrf_log_backend_enable(&m_crash_log_backend);
}

The sdk_config was modified to use:

NRF_QUEUE_ENABLED 0

RF_LOG_BACKEND_FLASH_ENABLED 1

NRF_LOG_BACKEND_FLASHLOG_ENABLED 1

NRF_LOG_BACKEND_FLASHLOG_QUEUE_SIZE 8

NRF_LOG_BACKEND_CRASHLOG_ENABLED 1

NRF_LOG_BACKEND_CRASHLOG_FIFO_SIZE 8

NRF_LOG_BACKEND_FLASH_SER_BUFFER_SIZE 64

NRF_LOG_BACKEND_FLASH_START_PAGE 0

NRF_LOG_BACKEND_PAGES 10

NRF_LOG_MSGPOOL_ELEMENT_COUNT 16

NRF_LOG_BUFSIZE 8192

NRF_LOG_FILTERS_ENABLED 1

I am reading the flash and getting the text using 

nrfjprog --readcode flashhex && python3 hex2dump.py flashhex > flash.txt

I also modified the linker to add a section for the flash storage.

I am not seeing the logs that were supposed to be stored in the flash.

What could I be doing wrong?

Thank you.

[Vidar Berg]

Hi,

Do you see anything stored in this flash page? The format of the log data might be different from what you expect - instead of storing log messages in cleartext we store it as serialized logger objects with pointers referencing hardcoded messages inside the application image itself. This is to avoid duplication of log messages in flash.

[corentind]

Thanks for the clarification regarding the format.

I see the firmware including the strings being stored in the flash but I don't think the logs are here.

I have been using the following function to test the flash:

void test_flashlog()
{

    // Test log reader
    ret_code_t error_code;
    uint32_t token = 0;
    nrf_log_header_t * p_header = NULL;
    uint8_t * p_data = NULL;
    NRF_LOG_INFO("Reading flash");

    while(true)
    {
        error_code = nrf_log_backend_flash_next_entry_get(&token, &p_header, &p_data);
        if(error_code != NRF_SUCCESS)
        {
            if(error_code == NRF_ERROR_NOT_FOUND)
            {
                NRF_LOG_INFO("Flash end reached");
            }
            else
            {
                NRF_LOG_WARNING("Read flash error code %d", error_code);
        }
        break;
        }
        else
        {
            NRF_LOG_INFO("Location %d", token);
            NRF_LOG_INFO("Read Data: %s", p_data);
            log_entry_process(p_header, p_data);
        }
    }
}

It returns that the flash end was reached straightaway as if it was empty.

I have a question -- Is the address where the logs are stored always at 0x52000? If not how to determine the address?

[Vidar Berg]

The flash log area starts directly after the application (ie first page aligned address) when NRF_LOG_BACKEND_FLASH_START_PAGE==0. But you can specify any fixed page address for NRF_LOG_BACKEND_FLASH_START_PAGE as long as it doesn't overlap with something else.

Are you able to debug the code and check if nrf_fstorage_write() calls are being made in the nrf_log_backend_flash.c?

[corentind]

Thank you.

I added some logging to the nrf_fstorage_write(). It looks like it gets called the first time I do an NRF_LOG_FLUSH() but not after. If I try to read the flash I still get "Flash end reached".

[Vidar Berg]

NRF_LOG_FLUSH() may cause the program to hang if called from an interrupt context as the asynchronous logger backends rely on various interrupts to come through to signal completion of a transfer (e.g., Softdevice use interrupt to notify the result of a flash operation to the app). Could that explain what happens here, or does the program appear to continue after the log flush? Also, have you tried to not start advertising/scanning in case BLE activity is interfering with the flash operations (flash scheduling with Softdevice)? 

I have tried to replicate this here as well. I took the ble_app_hrs from SDK 16.0.0 and added the code you posted here. It's attached below if you wish to compare it against yours.

ble_app_hrs_w_flashlog.zip

[gilbertjuly]

Vidar, I don't understand... from the picture, the address to where log is stored is 0x0004e41c, how come 0x52000 is the log entry? Could you please explain more? Thank you.