Strings with Flashlog

[jspear]

Hi all,

I am hoping to eventually integrate the crashlog functionality, but prior to this, I wanted to test the basic functionality with the flashlog. I have looked through posts like this and this, but I am still not able to understand the flashlog functionality properly. I am starting with a pruned version of the cli_usbd_only example code, and currently have the following:

#include <stdio.h>
#include <stdbool.h>
#include <stddef.h>

#include "nrf.h"
#include "nrf_drv_clock.h"
#include "nrf_gpio.h"
#include "nrf_delay.h"

#include "app_timer.h"
#include "fds.h"
#include "app_error.h"
#include "app_util.h"

#include "nrf_cli.h"
#include "nrf_cli_rtt.h"
#include "nrf_cli_types.h"

#include "boards.h"

#include "nrf_log.h"
#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"
#include "nrf_log_backend_flash.h"
#include "nrf_fstorage_nvmc.h"

#include "nrf_mpu_lib.h"
#include "nrf_stack_guard.h"

#include "nrf_cli_cdc_acm.h"
#include "nrf_drv_usbd.h"
#include "app_usbd_core.h"
#include "app_usbd.h"
#include "app_usbd_string_desc.h"
#include "app_usbd_cdc_acm.h"


#if NRF_LOG_BACKEND_FLASHLOG_ENABLED
    NRF_LOG_BACKEND_FLASHLOG_DEF(m_flash_log_backend);
#endif


#if defined(NRF_LOG_BACKEND_RTT_ENABLED) && NRF_LOG_BACKEND_RTT_ENABLED
    #include "nrf_log_backend_rtt.h"
    NRF_LOG_BACKEND_RTT_DEF(rtt_log_backend);
#endif


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

#if defined(NRF_LOG_BACKEND_RTT_ENABLED) && NRF_LOG_BACKEND_RTT_ENABLED
    nrf_log_backend_rtt_init();
    backend_id = nrf_log_backend_add(&rtt_log_backend, NRF_LOG_SEVERITY_DEBUG);
    ASSERT(backend_id >= 0);
    nrf_log_backend_enable(&rtt_log_backend);
#endif

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

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

#endif

}


int main(void)
{
    ret_code_t ret;
    bsp_board_init(BSP_INIT_LEDS);

    APP_ERROR_CHECK(NRF_LOG_INIT(NULL));

    flashlog_init();

    bsp_board_leds_on();
    bsp_board_led_on(0);
    nrf_delay_ms(1000);

    uint32_t p_tok = 0;

    nrf_log_header_t* p_header = NULL;
    uint8_t* p_data = NULL;

    int test = 0;

    nrf_log_backend_enable(&m_flash_log_backend);

    while (true)
    {
        UNUSED_RETURN_VALUE(NRF_LOG_PROCESS());

        if(test == 200)
        {
            while(nrf_log_backend_flash_next_entry_get(&p_tok, &p_header, &p_data) == NRF_SUCCESS)
            {
                NRF_LOG_HEXDUMP_INFO(p_data, 32);
            }
        }
        if((test == 100))
        {
            NRF_LOG_ERROR("0123");
        }

        nrf_delay_ms(30);
        test++;
    }
}

And the configurations are:

// <h> nRF_Log 

//==========================================================
// <e> NRF_LOG_BACKEND_FLASH_ENABLED - nrf_log_backend_flash - Log flash backend
//==========================================================
#ifndef NRF_LOG_BACKEND_FLASH_ENABLED
#define NRF_LOG_BACKEND_FLASH_ENABLED 1
#endif
// <q> NRF_LOG_BACKEND_FLASH_CLI_CMDS  - Enable CLI commands for this module.
 

#ifndef NRF_LOG_BACKEND_FLASH_CLI_CMDS
#define NRF_LOG_BACKEND_FLASH_CLI_CMDS 0
#endif

// <e> NRF_LOG_BACKEND_FLASHLOG_ENABLED - Enable flashlog backend.
//==========================================================
#ifndef NRF_LOG_BACKEND_FLASHLOG_ENABLED
#define NRF_LOG_BACKEND_FLASHLOG_ENABLED 1
#endif
// <o> NRF_LOG_BACKEND_FLASHLOG_QUEUE_SIZE - Logger messages queue size. 
// <i> Queue holds log messages pending to be written to flash.
// <i> Note that the queue holds logger messages and thus the queue size determines
// <i> increasing the pool of logger messages (see log message pool configuration).

#ifndef NRF_LOG_BACKEND_FLASHLOG_QUEUE_SIZE
#define NRF_LOG_BACKEND_FLASHLOG_QUEUE_SIZE 8
#endif

// </e>

// <e> NRF_LOG_BACKEND_CRASHLOG_ENABLED - Enable crashlog backend.
//==========================================================
#ifndef NRF_LOG_BACKEND_CRASHLOG_ENABLED
#define NRF_LOG_BACKEND_CRASHLOG_ENABLED 0
#endif
// <o> NRF_LOG_BACKEND_CRASHLOG_FIFO_SIZE - Number of log messages held to be flushed in panic. 
// <i> Crashlog FIFO always keeps a defined number of the most
// <i> recent logs (severity level is set on runtime).
// <i> Note that the FIFO holds logger messages and thus the FIFO size determines
// <i> increasing the pool of logger messages (see log message pool configuration).

#ifndef NRF_LOG_BACKEND_CRASHLOG_FIFO_SIZE
#define NRF_LOG_BACKEND_CRASHLOG_FIFO_SIZE 8
#endif

// </e>

// <o> NRF_LOG_BACKEND_FLASH_SER_BUFFER_SIZE - Size of the buffer used for serialize log message. 
// <i> Message is trimmed if it is longer. It may happen in case of 
// <i> hexdump message. Buffer size must be multiple of 4.

#ifndef NRF_LOG_BACKEND_FLASH_SER_BUFFER_SIZE
#define NRF_LOG_BACKEND_FLASH_SER_BUFFER_SIZE 64
#endif

// <h> Flash log location - Configuration of flash area used for storing the logs.

//==========================================================
// <o> NRF_LOG_BACKEND_FLASH_START_PAGE - Starting page.  
// <i> If 0, then pages directly after the application are used.

#ifndef NRF_LOG_BACKEND_FLASH_START_PAGE
#define NRF_LOG_BACKEND_FLASH_START_PAGE 0
#endif

// <o> NRF_LOG_BACKEND_PAGES - Number of pages. 
#ifndef NRF_LOG_BACKEND_PAGES
#define NRF_LOG_BACKEND_PAGES 1
#endif

// </h> 
//==========================================================

// </e>

// <e> NRF_LOG_BACKEND_RTT_ENABLED - nrf_log_backend_rtt - Log RTT backend
//==========================================================
#ifndef NRF_LOG_BACKEND_RTT_ENABLED
#define NRF_LOG_BACKEND_RTT_ENABLED 1
#endif
// <o> NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE - Size of buffer for partially processed strings. 
// <i> Size of the buffer is a trade-off between RAM usage and processing.
// <i> if buffer is smaller then strings will often be fragmented.
// <i> It is recommended to use size which will fit typical log and only the
// <i> longer one will be fragmented.

#ifndef NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE
#define NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE 64
#endif

// <o> NRF_LOG_BACKEND_RTT_TX_RETRY_DELAY_MS - Period before retrying writing to RTT 
#ifndef NRF_LOG_BACKEND_RTT_TX_RETRY_DELAY_MS
#define NRF_LOG_BACKEND_RTT_TX_RETRY_DELAY_MS 1
#endif

// <o> NRF_LOG_BACKEND_RTT_TX_RETRY_CNT - Writing to RTT retries. 
// <i> If RTT fails to accept any new data after retries
// <i> module assumes that host is not active and on next
// <i> request it will perform only one write attempt.
// <i> On successful writing, module assumes that host is active
// <i> and scheme with retry is applied again.

#ifndef NRF_LOG_BACKEND_RTT_TX_RETRY_CNT
#define NRF_LOG_BACKEND_RTT_TX_RETRY_CNT 3
#endif

// </e>

// <e> NRF_LOG_BACKEND_UART_ENABLED - nrf_log_backend_uart - Log UART backend
//==========================================================
#ifndef NRF_LOG_BACKEND_UART_ENABLED
#define NRF_LOG_BACKEND_UART_ENABLED 0
#endif
// <o> NRF_LOG_BACKEND_UART_TX_PIN - UART TX pin 
#ifndef NRF_LOG_BACKEND_UART_TX_PIN
#define NRF_LOG_BACKEND_UART_TX_PIN 6
#endif

// <o> NRF_LOG_BACKEND_UART_BAUDRATE  - Default Baudrate
 
// <323584=> 1200 baud 
// <643072=> 2400 baud 
// <1290240=> 4800 baud 
// <2576384=> 9600 baud 
// <3862528=> 14400 baud 
// <5152768=> 19200 baud 
// <7716864=> 28800 baud 
// <10289152=> 38400 baud 
// <15400960=> 57600 baud 
// <20615168=> 76800 baud 
// <30801920=> 115200 baud 
// <61865984=> 230400 baud 
// <67108864=> 250000 baud 
// <121634816=> 460800 baud 
// <251658240=> 921600 baud 
// <268435456=> 1000000 baud 

#ifndef NRF_LOG_BACKEND_UART_BAUDRATE
#define NRF_LOG_BACKEND_UART_BAUDRATE 30801920
#endif

// <o> NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE - Size of buffer for partially processed strings. 
// <i> Size of the buffer is a trade-off between RAM usage and processing.
// <i> if buffer is smaller then strings will often be fragmented.
// <i> It is recommended to use size which will fit typical log and only the
// <i> longer one will be fragmented.

#ifndef NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE
#define NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE 64
#endif

// </e>

// <e> NRF_LOG_ENABLED - nrf_log - Logger
//==========================================================
#ifndef NRF_LOG_ENABLED
#define NRF_LOG_ENABLED 1
#endif
// <h> Log message pool - Configuration of log message pool

//==========================================================
// <o> NRF_LOG_MSGPOOL_ELEMENT_SIZE - Size of a single element in the pool of memory objects. 
// <i> If a small value is set, then performance of logs processing
// <i> is degraded because data is fragmented. Bigger value impacts
// <i> RAM memory utilization. The size is set to fit a message with
// <i> a timestamp and up to 2 arguments in a single memory object.

#ifndef NRF_LOG_MSGPOOL_ELEMENT_SIZE
#define NRF_LOG_MSGPOOL_ELEMENT_SIZE 20
#endif

// <o> NRF_LOG_MSGPOOL_ELEMENT_COUNT - Number of elements in the pool of memory objects 
// <i> If a small value is set, then it may lead to a deadlock
// <i> in certain cases if backend has high latency and holds
// <i> multiple messages for long time. Bigger value impacts
// <i> RAM memory usage.

#ifndef NRF_LOG_MSGPOOL_ELEMENT_COUNT
#define NRF_LOG_MSGPOOL_ELEMENT_COUNT 16
#endif

// </h> 
//==========================================================

// <q> NRF_LOG_ALLOW_OVERFLOW  - Configures behavior when circular buffer is full.
 

// <i> If set then oldest logs are overwritten. Otherwise a 
// <i> marker is injected informing about overflow.

#ifndef NRF_LOG_ALLOW_OVERFLOW
#define NRF_LOG_ALLOW_OVERFLOW 0
#endif

// <o> NRF_LOG_BUFSIZE  - Size of the buffer for storing logs (in bytes).
 

// <i> Must be power of 2 and multiple of 4.
// <i> If NRF_LOG_DEFERRED = 0 then buffer size can be reduced to minimum.
// <128=> 128 
// <256=> 256 
// <512=> 512 
// <1024=> 1024 
// <2048=> 2048 
// <4096=> 4096 
// <8192=> 8192 
// <16384=> 16384 

#ifndef NRF_LOG_BUFSIZE
#define NRF_LOG_BUFSIZE 1024
#endif

// <q> NRF_LOG_CLI_CMDS  - Enable CLI commands for the module.
 

#ifndef NRF_LOG_CLI_CMDS
#define NRF_LOG_CLI_CMDS 0
#endif

// <o> NRF_LOG_DEFAULT_LEVEL  - Default Severity level
 
// <0=> Off 
// <1=> Error 
// <2=> Warning 
// <3=> Info 
// <4=> Debug 

#ifndef NRF_LOG_DEFAULT_LEVEL
#define NRF_LOG_DEFAULT_LEVEL 3
#endif

// <q> NRF_LOG_DEFERRED  - Enable deffered logger.
 

// <i> Log data is buffered and can be processed in idle.

#ifndef NRF_LOG_DEFERRED
#define NRF_LOG_DEFERRED 1
#endif

// <q> NRF_LOG_FILTERS_ENABLED  - Enable dynamic filtering of logs.
 

#ifndef NRF_LOG_FILTERS_ENABLED
#define NRF_LOG_FILTERS_ENABLED 0
#endif

// <q> NRF_LOG_NON_DEFFERED_CRITICAL_REGION_ENABLED  - Enable use of critical region for non deffered mode when flushing logs.
 

// <i> When enabled NRF_LOG_FLUSH is called from critical section when non deffered mode is used.
// <i> Log output will never be corrupted as access to the log backend is exclusive
// <i> but system will spend significant amount of time in critical section

#ifndef NRF_LOG_NON_DEFFERED_CRITICAL_REGION_ENABLED
#define NRF_LOG_NON_DEFFERED_CRITICAL_REGION_ENABLED 0
#endif

// <o> NRF_LOG_STR_PUSH_BUFFER_SIZE  - Size of the buffer dedicated for strings stored using @ref NRF_LOG_PUSH.
 
// <16=> 16 
// <32=> 32 
// <64=> 64 
// <128=> 128 
// <256=> 256 
// <512=> 512 
// <1024=> 1024 

#ifndef NRF_LOG_STR_PUSH_BUFFER_SIZE
#define NRF_LOG_STR_PUSH_BUFFER_SIZE 128
#endif

// <o> NRF_LOG_STR_PUSH_BUFFER_SIZE  - Size of the buffer dedicated for strings stored using @ref NRF_LOG_PUSH.
 
// <16=> 16 
// <32=> 32 
// <64=> 64 
// <128=> 128 
// <256=> 256 
// <512=> 512 
// <1024=> 1024 

#ifndef NRF_LOG_STR_PUSH_BUFFER_SIZE
#define NRF_LOG_STR_PUSH_BUFFER_SIZE 128
#endif

// <e> NRF_LOG_USES_COLORS - If enabled then ANSI escape code for colors is prefixed to every string
//==========================================================
#ifndef NRF_LOG_USES_COLORS
#define NRF_LOG_USES_COLORS 1
#endif
// <o> NRF_LOG_COLOR_DEFAULT  - ANSI escape code prefix.
 
// <0=> Default 
// <1=> Black 
// <2=> Red 
// <3=> Green 
// <4=> Yellow 
// <5=> Blue 
// <6=> Magenta 
// <7=> Cyan 
// <8=> White 

#ifndef NRF_LOG_COLOR_DEFAULT
#define NRF_LOG_COLOR_DEFAULT 0
#endif

// <o> NRF_LOG_ERROR_COLOR  - ANSI escape code prefix.
 
// <0=> Default 
// <1=> Black 
// <2=> Red 
// <3=> Green 
// <4=> Yellow 
// <5=> Blue 
// <6=> Magenta 
// <7=> Cyan 
// <8=> White 

#ifndef NRF_LOG_ERROR_COLOR
#define NRF_LOG_ERROR_COLOR 2
#endif

// <o> NRF_LOG_WARNING_COLOR  - ANSI escape code prefix.
 
// <0=> Default 
// <1=> Black 
// <2=> Red 
// <3=> Green 
// <4=> Yellow 
// <5=> Blue 
// <6=> Magenta 
// <7=> Cyan 
// <8=> White 

#ifndef NRF_LOG_WARNING_COLOR
#define NRF_LOG_WARNING_COLOR 4
#endif

// </e>

// <e> NRF_LOG_USES_TIMESTAMP - Enable timestamping

// <i> Function for getting the timestamp is provided by the user
//==========================================================
#ifndef NRF_LOG_USES_TIMESTAMP
#define NRF_LOG_USES_TIMESTAMP 0
#endif
// <o> NRF_LOG_TIMESTAMP_DEFAULT_FREQUENCY - Default frequency of the timestamp (in Hz) or 0 to use app_timer frequency. 
#ifndef NRF_LOG_TIMESTAMP_DEFAULT_FREQUENCY
#define NRF_LOG_TIMESTAMP_DEFAULT_FREQUENCY 0
#endif

// </e>

// <h> nrf_log module configuration 

//==========================================================
// <h> nrf_log in nRF_Core 

The attempt is to have a basic "0123" written to the Flash and RTT, read the flashlog entries, and then double check that what was stored is the same as what was put into it. I understand that based on one of the earlier mentioned posts that the string data is reused and a pointer to the string in flash is stored rather than copying the string multiple times. How am I supposed to go about properly reading the stored flashlog data in real time?

Thanks for any help you can give!

Joseph

[Einar Thorsrud]

Hi Joseph,

How am I supposed to go about properly reading the stored flashlog data in real time?

You should probably not. If this is the goal, then I don't see why you would want to use flash logging. There is CLI support in the flash backend and you can look at that for how to fetch logs from flash runtime (see Logger module documentation). I do not see much practical use of this in a real product, though. I shoudl add that I do not see the flash backend much used, which I believe there are a few reasons for.

Logging to flash is mostly usefull for crash logs or very limited logging, as writing to flash takes time, and is also an asyncrhoneous operation that is scheduled by the SoftDevice. So if you are doing a lot of logging the flash backend is not a good option. Aso, it could be that in a bad state, it will not be possible to write to flash, so there are other more robust ways to do crash logging - one is to write debug information to a noinit RAM buffer (with a checksum), and check the content of that buffer at every boot to see if there is something, and then write it to flash (this is will not be using the logger module).

Einar

[jspear]

Einar,

Thanks for the reply and that makes sense that I wouldn't want to use flashlog often. Like I mentioned, our ultimate goal is to use the crashlog functionality, so I was hoping to use flashlog to test out the similar functionality without having to force a crash to test the crashlog.

That being said, while it may not be a great idea to be putting logs into the flash memory often with flashlog, would it work to send string data related to the error using the crashlog, or would I be running into the same issues? What would be the appropriate way to log crash information using the crashlog module?

Thanks!

[Einar Thorsrud]

Hi,

Regarding flash logging you can look at this sample that a colleague of me made and attached to this post (this does not use crash log).

Honestly, I do not recall seeing many questions about the crashlog feature in the logger module and I believe it is very little used (perhaps related to what I wrote before). You can see how it is used in the CLI examples, but that is the only reference we have for it.

I would suggeest a different approach though, as mentionned before. There are cases where writing to flash after an error is simply not possible. This is also the case after for instance a WDT has timed out. In that case you have two 32.768 kHz clock cycles after the TIMEOUT event where you can write debug information, but this is not enough time to write to flash. So writing whatever debuginformation you want to a RAM buffer and then writing to flash after reset is the most robust way (which we sometimes see used in big projects). Note that RAM content is not guaranteed after a WDT reset or a soft reset, but it is also not explicitly cleared, and in most cases it will be intact (provided buffer is noinit), which is why you need a checksum.

[jspear]

Einar,

That makes a lot of sense and I appreciate the clarification! I'll look into using the RAM buffer as a method for error analysis.

Thanks!