flashlog loses pushed string contents

[Brian]

Hi,

  I'm using the flashlog on my nRF52840 to log events.  I have an external RTC which I read when logging each event in order to timestamp the event.  My RTC code writes to a static char array, and I use NRF_LOG_PUSH to save the value when I log the event.  Doing a "flashlog read" after logging several events works as expected - I get my timestamped event logs.  However, if I cycle power to the device and again read the flashlog, I see the events that were previously there, but the timestamp is missing.

  Here's the sdk_config.h values of interest -

#define FDS_ENABLED                           1

#define NRF_FSTORAGE_ENABLED                  1

#define NRF_LOG_BACKEND_FLASH_ENABLED         1

#define NRF_LOG_BACKEND_FLASHLOG_ENABLED      1

#define NRF_LOG_BACKEND_FLASHLOG_QUEUE_SIZE   8

#define NRF_LOG_BACKEND_FLASH_SER_BUFFER_SIZE 64

#define NRF_LOG_BACKEND_FLASH_START_PAGE      0xE0

#define NRF_LOG_BACKEND_PAGES                 4

#define NRF_LOG_BACKEND_UART_ENABLED          1

#define NRF_LOG_BACKEND_UART_BAUDRATE         30801920

#define NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE 256

#define NRF_LOG_MSGPOOL_ELEMENT_COUNT         16

#define NRF_LOG_FILTERS_ENABLED               1

#define NRF_LOG_USES_TIMESTAMP                1

#define NRF_LOG_TIMESTAMP_DEFAULT_FREQUENCY   1000

#define NRF_FSTORAGE_ENABLED                  1

#define NRF_QUEUE_ENABLED                     1

#define FDS_ENABLED                           1

#define NRF_LOG_STR_PUSH_BUFFER_SIZE          8192

#define NRF_LOG_BUFSIZE                       16384

  I have also tried enabling NRF_LOG_NON_DEFFERED_CRITICAL_REGION_ENABLED, but that had no affect.

  My code to log an event looks like this -

            static char *p_dt;
            p_dt = logging_datetime_get();
            NRF_LOG_WARNING("%s Entering state idle2.", NRF_LOG_PUSH(p_dt));

  This produces the following result on a flashlog read - 

[00:01:54.610,000] <warning> app: (2021-Sep-01: 12:02:12) Entering state idle2.

  If I power cycle, and then read the flashlog again, I get - 

[00:01:54.610,000] <warning> app: Entering state idle2.

  My background loop calls NRF_LOG_PROCESS() each time through the loop.

  Is there a way to retain my RTC strings in the flashlog across a power cycle?

  Thanks...

Brian

[Jared]

Hi,

What SDK version are you using?

After the power cycle, could you pause the application after logging_datetime_get() with a debugger and see what p_dt is set to in debug view?

regards

Jared 

Also, we're short on staff due to the Holiday season. Expect some delay in the handling of this case. 

[Brian]

Hi Jared,

  I'm using SDK 17.0.2.

  After a power cycle, p_dt contains the address of the variable dt_str (0x2000 d548).  dt_str is the statically-declared variable that gets updated by the logging_datetime_get() function -

#define DATE_TIME_STR_SIZE 32

static char          dt_str[DATE_TIME_STR_SIZE];
static char*         month_str[NUM_MONTHS + 1]  = {"Inv", "Jan", "Feb", "Mar", "Apr", "May", "Jun",
                                          "Jul", "Aug", "Sep", "Oct", "Nov", "Dec"};

char* logging_datetime_get(void)
{
    error_status_t err;
    date_time_t    date_time;

    err = pcf8563_datetime_get(rtc_handle, &date_time);

    if (err == ERROR_OK)
    {
        (void)snprintf(dt_str, DATE_TIME_STR_SIZE, "(20%02d-%s-%02d: %02d:%02d:%02d)", date_time.year,
                       month_str[date_time.month], date_time.day, date_time.hour, date_time.minute, date_time.second);
    }

    return dt_str;
}

 

  I understand that after a power cycle, p_dt will not point to the correct timestamp data for previous entries in the flashlog.  My assumption was that using NRF_LOG_PUSH would save the contents of the string, which in this case would be the timestamp when the event was first logged.

  Thanks.

Brian

[Hung Bui]

Hei Brian, 

I'm sorry for late response. Jared is on vacation so I will take over the case. 

If you have a look at this case handled by Vidar : https://devzone.nordicsemi.com/f/nordic-q-a/58111/implement-flashlog-backend

He explained a little bit more about how flashlog is stored and on that the variable is stored at a different location compare to the static log (e.g "Entering state idle2") . It may explain why you only see the static one not the date and time. 

[Brian]

I was able to resolve this by storing my RTC data as multiple separate integer values rather than just one string.  I believe this allows each value to be stored in the flashlog rather than a pointer to a single location.

[Hung Bui]

Hi Brian, 
Thanks for the info. I think we have an idea of what could be wrong here.
Since you declared the p_dt as static string, the logger module would assume it's a static text, just like the other text "Entering state idle2" and use a reference to it like what Vidar explained. But the problem is that it's stored in RAM not flash. So when you have a power reset, the static string is gone and you don't see it anymore. 
But when you store them as integer ( I would assume without static ) it's treated as variable and will be stored as a new entry in flash log every time you push.