NvStore does not correctly persist values through reset

[NeilMacMullen]

Description

TARGET=UBLOX_EVK_NINA_B1 (nrf52)
TOOLCHAIN=GCC_ARM
MBED commit bf6f2c3 (but also present at least as far back as commit a8abecc)

The NvStore implementation does not appear to persist values through a soft-reset. It seems likely that it is mis-identifying the active page. This may be related to increasing the max_keys count above the default. The following code is self-contained apart from the implementation of DEBUGLN which is just a shim over segger_rtt-printf. You can replace it with whatever tracing mechanism you prefer.

The test first sets item #1 then resets and changes the value after also adding a new item (#27). Both items are correctly listed until the CPU is reset. After reset the old value of item #1 is seen and the new item #27 is not present. The expected behaviour is that the test should continue to the 'final' section but it continuously loops through the "second run" block.

#include "mbed.h"
#include "debugln.h"
#include "nvstore.h"

//#define CLEANBOARD
#define MAX_SETTING_VALUE_LENGTH (32)
#define MAX_KEYS 128
#define RESET NVIC_SystemReset()

//ensure strings are correctly aligned to a uint32 boundary
typedef union {
    uint32_t Numeric;
    char String[MAX_SETTING_VALUE_LENGTH];
} nvstore_item_value_t;

#define MYASSERT(OP, EXPECTED, MESSAGE)                             \
    {                                                               \
        int err = OP;                                               \
        if (err != EXPECTED)                                        \
        {                                                           \
            DEBUGLN("FAIL: Got %d but expected %d", err, EXPECTED); \
            HALT(MESSAGE);                                          \
        }                                                           \
    }

bool TryGetNvStoreItem(int id, nvstore_item_value_t &value)
{
    NVStore &nvstore = NVStore::get_instance();
    uint16_t size_read;
    value.String[0] = 0;
    int err = nvstore.get(id, sizeof(nvstore_item_value_t), value.String, size_read);
    return (err == NVSTORE_SUCCESS) && size_read;
}

void WriteNvStoreItem(int id, nvstore_item_value_t &value)
{
    NVStore &nvstore = NVStore::get_instance();
    int len = strlen(value.String) + 1;
    MYASSERT(nvstore.set(id, len, value.String), NVSTORE_SUCCESS, "Failed to write setting");
}

void WriteAndVerifyItem(int n, char *val)
{
    nvstore_item_value_t write_item;
    strcpy(write_item.String, val);
    WriteNvStoreItem(n, write_item);
    nvstore_item_value_t read_item;
    MYASSERT(TryGetNvStoreItem(n, read_item), true, "Failed to read back setting that we just wrote");
    MYASSERT(strcmp(val, read_item.String), 0, "Read different value back than written");
}

void ListNvStoreItems(char *message)
{
    DEBUGLN("%s", message);
    for (int n = 0; n < MAX_KEYS; n++)
    {
        nvstore_item_value_t read_item;
        if (TryGetNvStoreItem(n, read_item))
            DEBUGLN("%d: '%s'", n, read_item.String);
    }
}

void RESETSTORE()
{
    NVStore &nvstore = NVStore::get_instance();
    nvstore.reset();
    HALT("reset store");
}

void EnsureMaxKeysCorrect()
{
    NVStore &nvstore = NVStore::get_instance();
    MYASSERT(nvstore.init(), NVSTORE_SUCCESS, "failed to init store");
    if (nvstore.get_max_keys() != MAX_KEYS)
        nvstore.set_max_keys(MAX_KEYS);
    MYASSERT(nvstore.get_max_keys(), MAX_KEYS, "Max keys has not been correctly set");
}

int main()
{
#ifdef CLEANBOARD
    RESETSTORE();
#endif

    DEBUGLN("======== entered main after reset ========");
    EnsureMaxKeysCorrect();
    ListNvStoreItems("Items on entry....");
    nvstore_item_value_t item1;
    if (!TryGetNvStoreItem(1, item1))
    {
        //Write "01" the first time we run the program
        DEBUGLN("First run so setting #1 to 01...");
        WriteAndVerifyItem(1, "01");
    }
    else
    {
        if (!strcmp(item1.String, "01"))
        {
            //On the second run, add a new key and increment item 1 to indicate that
            //we can move on....
            DEBUGLN("second run so item #1 to 02 and adding extra item...");
            WriteAndVerifyItem(27, "abcded");
            WriteAndVerifyItem(1, "02");
        }
        else
        {
            //this should be the 3rd (and final) run but we never get here :(
            ListNvStoreItems("Final items");
            HALT("Test passed");
        }
    }
    ListNvStoreItems("Items on exit...");
    DEBUGLN("resetting in 10 seconds...");
    wait_ms(10000);
    RESET;
}

Example output....

0> ======== entered main after reset ========
0> Items on entry....
0> First run so setting #1 to 01...
0> Items on exit...
0> 1: '01'
0> resetting in 10 seconds...
0> entered main after reset ========
0> ======== entered main after reset ========
0> Items on entry....
0> 1: '01'
0> second run so item #1 to 02 and adding extra item...
0> Items on exit...
0> 1: '02'
0> 27: 'abcded'
0> resetting in 10 seconds...
0> ======== entered main after reset ========
0> Items on entry....
0> 1: '01'
0> second run so item #1 to 02 and adding extra item...
0> Items on exit...
0> 1: '02'
0> 27: 'abcded'
0> resetting in 10 seconds...
0> ======== entered main after reset ========
0> Items on entry....
0> 1: '01'
0> second run so item #1 to 02 and adding extra item...
0> Items on exit...
0> 1: '02'
0> 27: 'abcded'
0> resetting in 10 seconds...

`

Issue request type

[ ] Question
[ ] Enhancement
[x] Bug

[NeilMacMullen]

Adding @MarceloSalazar

[ciarmcom]

Internal Jira reference: https://jira.arm.com/browse/MBOCUSTRIA-176

[0xc0170]

@ARMmbed/mbed-os-storage Please review

[NeilMacMullen]

The set_max_keys functionality is fundamentally broken:

set_max_keys immediately calls MBED_ASSERT(num_keys < get_max_possible_keys()); before setting _max_keys

get_max_possible_keys() results in a lazy call to init

init calls read-record for each entry in the store

read_record considers the record to be invalid if the key number is greater than the current number of _max_keys (which will be the default at this stage).

init then considers the key to be corrupt and calls garbage collection

So if, in the past, _max_keys was increased beyond the default and a key with a higher id was stored, it will immediately be garbage collected on the first use of the store after a reset.

A workaround is to remove this check from read_record

  if ((key >= _max_keys) && (key != master_record_key))
    {
        valid = 0;
        return NVSTORE_SUCCESS;
    }

but a real fix would be to treat the maximum number of keys as a persistent value.

The current API doesn't make a lot of sense - it suggests you can dynamically change the number of stored items but even without this bug, that would have unpleasant consequences if you reduced the number after storing a few. A better and more flexible design might simply be to remove the "max_keys" concept entirely and just treat the id as a tag which would both avoid this problem and allow clients more flexibility in assigning ids.

Also, a comment on the tests.... I can't see any indication that the tests perform a physical reset of the target which would seem to be a fairly important aspect of the behaviour. (nvstore.reset is used instead)There is no test to ensure that keys 'survive' an increase of _max_keys but even if there were it wouldn't be picked up in this test-set because nvstore.reset doesn't clear all the state (most notably _max_keys) associated with the store.

[NeilMacMullen]

Further comment - the suggested workaround above is actually unsafe since it will result in _offset_by_key[high_id] being written even if high_id is >= _max_keys. So far the best alternative I've found is to remove the ASSERT from set_max_keys and to be very careful to call set_max_keys as the very first thing.

As far as I can tell, the use of this fixed-size lookup table (offset_by_key) is the main impediment to moving to a tag-based system but given that keys are read/written relatively rarely, dynamically calculating the offset for each read/write would seem like a reasonable alternative..