NVS iterator does not seem to return all matching entries (IDFGH-2910)

[alyf80]

Module or chip used: ESP32-WROOM-32
IDF version: v4.0-223-gfdbdf9a0e
Build System: CMake
Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2019r2) 8.2.0
Operating System: Linux

Hello,
I am trying to iterate over all entries in an NVS partition using nvs_entry_find() as per the documentation; however it seems that some entries are being skipped.

The missing entries can be read normally with open/get/close.

Dumping the partition (with nvs_dump() from nvs_test_api.h) shows that the entries being missed are the last two.

The problem seems to be related to the partition's contents or layout: it is fully reproducible on this partition, and erasing the partition and recreating its contents does not fix it. However, I have another NVS partition with different contents whose entries I can iterate on successfully.

Test code:

#include <stdio.h>

#include <esp_err.h>
#include <nvs.h>
#include <nvs_flash.h>

void nvs_dump();

void test(const char *part) {
    ESP_ERROR_CHECK(nvs_flash_init_partition(part));
    nvs_dump(part);

    printf("start -------\n");
    nvs_iterator_t it = nvs_entry_find(part, NULL, NVS_TYPE_ANY);
    nvs_entry_info_t info;

    while (it) {
        nvs_entry_info(it, &info);
        printf("%s::%s type=%d\n", info.namespace_name, info.key, info.type);
        it = nvs_entry_next(it);
    }

    printf("end -------\n\n");
}

void app_main() {
    test("nvs"); // good
    test("ble_mesh"); // bad
}

Output:

state=fffffffe (ACTIVE) addr=9000 seq=0
firstUsed=0 nextFree=79 used=78 erased=1
  0: W ns= 0 type= 1 span=  1 key="box_attrs" chunkIdx=255 len=-1
  1: W ns= 1 type= 1 span=  1 key="flags" chunkIdx=255 len=-1
  2: W ns= 0 type= 1 span=  1 key="bm_hack" chunkIdx=255 len=-1
  3: X
  4: W ns= 0 type= 1 span=  1 key="phy" chunkIdx=255 len=-1
  5: W ns= 3 type=66 span= 61 key="cal_data" chunkIdx=0 len=1904
  6: D
  7: D
  8: D
  9: D
 10: D
 11: D
 12: D
 13: D
 14: D
 15: D
 16: D
 17: D
 18: D
 19: D
 20: D
 21: D
 22: D
 23: D
 24: D
 25: D
 26: D
 27: D
 28: D
 29: D
 30: D
 31: D
 32: D
 33: D
 34: D
 35: D
 36: D
 37: D
 38: D
 39: D
 40: D
 41: D
 42: D
 43: D
 44: D
 45: D
 46: D
 47: D
 48: D
 49: D
 50: D
 51: D
 52: D
 53: D
 54: D
 55: D
 56: D
 57: D
 58: D
 59: D
 60: D
 61: D
 62: D
 63: D
 64: D
 65: D
 66: W ns= 3 type=72 span=  1 key="cal_data" chunkIdx=255 len=-1
 67: W ns= 3 type=66 span=  2 key="cal_mac" chunkIdx=0 len=6
 68: D
 69: W ns= 3 type=72 span=  1 key="cal_mac" chunkIdx=255 len=-1
 70: W ns= 3 type= 4 span=  1 key="cal_version" chunkIdx=255 len=-1
 71: W ns= 0 type= 1 span=  1 key="nimble_bond" chunkIdx=255 len=-1
 72: W ns= 0 type= 1 span=  1 key="NDB_0" chunkIdx=255 len=-1
 73: W ns= 5 type=66 span=  2 key="000D" chunkIdx=0 len=10
 74: D
 75: W ns= 5 type=72 span=  1 key="000D" chunkIdx=255 len=-1
 76: W ns= 5 type=66 span=  2 key="000" chunkIdx=0 len=17
 77: D
 78: W ns= 5 type=72 span=  1 key="000" chunkIdx=255 len=-1
 79: E
 80: E
 81: E
 82: E
 83: E
 84: E
 85: E
 86: E
 87: E
 88: E
 89: E
 90: E
 91: E
 92: E
 93: E
 94: E
 95: E
 96: E
 97: E
 98: E
 99: E
100: E
101: E
102: E
103: E
104: E
105: E
106: E
107: E
108: E
109: E
110: E
111: E
112: E
113: E
114: E
115: E
116: E
117: E
118: E
119: E
120: E
121: E
122: E
123: E
124: E
125: E
start -------
box_attrs::flags type=1
phy::cal_data type=66
phy::cal_mac type=66
phy::cal_version type=4
NDB_0::000D type=66
NDB_0::000 type=66
end -------

state=fffffffe (ACTIVE) addr=11000 seq=0
firstUsed=0 nextFree=83 used=62 erased=21
  0: W ns= 0 type= 1 span=  1 key="mesh_core" chunkIdx=255 len=-1
  1: W ns= 0 type= 1 span=  1 key="mesh_server" chunkIdx=255 len=-1
  2: W ns= 1 type=66 span=  2 key="mesh/p_prov" chunkIdx=0 len=4
  3: D
  4: W ns= 1 type=72 span=  1 key="mesh/p_prov" chunkIdx=255 len=-1
  5: W ns= 1 type=66 span=  2 key="mesh/p_netidx" chunkIdx=0 len=2
  6: D
  7: W ns= 1 type=72 span=  1 key="mesh/p_netidx" chunkIdx=255 len=-1
  8: W ns= 1 type=66 span=  2 key="mesh/p_appidx" chunkIdx=0 len=2
  9: D
 10: W ns= 1 type=72 span=  1 key="mesh/p_appidx" chunkIdx=255 len=-1
 11: W ns= 1 type=66 span=  3 key="mesh/pnk/0000" chunkIdx=0 len=33
 12: D
 13: D
 14: W ns= 1 type=72 span=  1 key="mesh/pnk/0000" chunkIdx=255 len=-1
 15: W ns= 1 type=66 span=  2 key="mesh/p_netkey" chunkIdx=0 len=2
 16: D
 17: W ns= 1 type=72 span=  1 key="mesh/p_netkey" chunkIdx=255 len=-1
 18: X
 19: X
 20: X
 21: W ns= 1 type=66 span=  3 key="mesh/pak/0000" chunkIdx=0 len=35
 22: D
 23: D
 24: W ns= 1 type=72 span=  1 key="mesh/pak/0000" chunkIdx=255 len=-1
 25: W ns= 1 type=66 span=  2 key="mesh/p_appkey" chunkIdx=0 len=2
 26: D
 27: W ns= 1 type=72 span=  1 key="mesh/p_appkey" chunkIdx=255 len=-1
 28: W ns= 1 type=66 span=  2 key="mesh/seq" chunkIdx=0 len=3
 29: D
 30: W ns= 1 type=72 span=  1 key="mesh/seq" chunkIdx=255 len=-1
 31: W ns= 1 type=66 span=  3 key="mesh/sn/0001/i" chunkIdx=0 len=51
 32: D
 33: D
 34: W ns= 1 type=72 span=  1 key="mesh/sn/0001/i" chunkIdx=255 len=-1
 35: W ns= 1 type=66 span=  2 key="mesh/p_snode" chunkIdx=0 len=2
 36: D
 37: W ns= 1 type=72 span=  1 key="mesh/p_snode" chunkIdx=255 len=-1
 38: X
 39: X
 40: X
 41: W ns= 1 type=66 span=  2 key="mesh/sn/0001/n" chunkIdx=128 len=31
 42: D
 43: W ns= 1 type=72 span=  1 key="mesh/sn/0001/n" chunkIdx=255 len=-1
 44: W ns= 1 type=66 span=  2 key="mesh/s/0002/b" chunkIdx=0 len=6
 45: D
 46: W ns= 1 type=72 span=  1 key="mesh/s/0002/b" chunkIdx=255 len=-1
 47: X
 48: X
 49: X
 50: W ns= 1 type=66 span=  2 key="mesh/s/0003/b" chunkIdx=0 len=6
 51: D
 52: W ns= 1 type=72 span=  1 key="mesh/s/0003/b" chunkIdx=255 len=-1
 53: X
 54: X
 55: X
 56: W ns= 1 type=66 span=  2 key="mesh/s/0100/b" chunkIdx=0 len=6
 57: D
 58: W ns= 1 type=72 span=  1 key="mesh/s/0100/b" chunkIdx=255 len=-1
 59: X
 60: X
 61: X
 62: W ns= 1 type=66 span=  2 key="mesh/s/0101/b" chunkIdx=0 len=6
 63: D
 64: W ns= 1 type=72 span=  1 key="mesh/s/0101/b" chunkIdx=255 len=-1
 65: X
 66: X
 67: X
 68: W ns= 1 type=66 span=  2 key="mesh/s/0200/b" chunkIdx=0 len=6
 69: D
 70: W ns= 1 type=72 span=  1 key="mesh/s/0200/b" chunkIdx=255 len=-1
 71: X
 72: X
 73: X
 74: W ns= 1 type=66 span=  2 key="mesh/s/0201/b" chunkIdx=0 len=6
 75: D
 76: W ns= 1 type=72 span=  1 key="mesh/s/0201/b" chunkIdx=255 len=-1
 77: W ns= 1 type=66 span=  2 key="mesh/sig" chunkIdx=128 len=12
 78: D
 79: W ns= 1 type=72 span=  1 key="mesh/sig" chunkIdx=255 len=-1
 80: W ns= 1 type=66 span=  2 key="mesh/role" chunkIdx=128 len=4
 81: D
 82: W ns= 1 type=72 span=  1 key="mesh/role" chunkIdx=255 len=-1
 83: E
 84: E
 85: E
 86: E
 87: E
 88: E
 89: E
 90: E
 91: E
 92: E
 93: E
 94: E
 95: E
 96: E
 97: E
 98: E
 99: E
100: E
101: E
102: E
103: E
104: E
105: E
106: E
107: E
108: E
109: E
110: E
111: E
112: E
113: E
114: E
115: E
116: E
117: E
118: E
119: E
120: E
121: E
122: E
123: E
124: E
125: E
start -------
mesh_core::mesh/p_prov type=66
mesh_core::mesh/p_netidx type=66
mesh_core::mesh/p_appidx type=66
mesh_core::mesh/pnk/0000 type=66
mesh_core::mesh/p_netkey type=66
mesh_core::mesh/pak/0000 type=66
mesh_core::mesh/p_appkey type=66
mesh_core::mesh/seq type=66
mesh_core::mesh/sn/0001/i type=66
mesh_core::mesh/p_snode type=66
mesh_core::mesh/s/0002/b type=66
mesh_core::mesh/s/0003/b type=66
mesh_core::mesh/s/0100/b type=66
mesh_core::mesh/s/0101/b type=66
mesh_core::mesh/s/0200/b type=66
mesh_core::mesh/s/0201/b type=66
end -------

mesh_core::mesh/sig and mesh_core:.mesh/role are missing from the second iteration.

Am I doing something wrong?

I can provide an image of the two partitions if needed.

Thanks,
andrea

[0xjakob]

Hi @alyf80, thanks for posting this issue! Yes, a partition image of the ble_mesh partition would be quite helpful. We'll have a look into this.

[0xjakob]

btw, the blob mesh_core::mesh/sn/0001/n isn't seen either by the itererator.

[alyf80]

Missed that...

Here is the partition image:
ble_mesh.zip

In case it matters, I am using this partition map:

# Name,         Type, SubType,  Offset,   Size,  Flags
nvs,            data, nvs,      0x09000,  0x8000
ble_mesh,       data, nvs,      0x11000,  0x8000
otadata,        data, ota,      0x19000,  0x2000
phy_init,       data, phy,      0x1B000,  0x1000
ota_0,          app,  ota_0,    0x20000,  0x1E0000
ota_1,          app,  ota_1,    0x200000, 0x1E0000
factory_nvs,    data, nvs,      0x3E0000, 0x4000
nvs_keys,       data, nvs_keys, 0x3E4000, 0x1000

[0xjakob]

Hi @alyf80. Seems like the problem is an incorrect handling of blobs here: https://github.com/espressif/esp-idf/blob/master/components/nvs_flash/src/nvs_storage.cpp#L766.
This function is used by the iterator. It basically tests whether an item in NVS is the biginning of a blob. if it's not, than it you don't need to visit it with the iterator because it's just another part of a blob which was visited before already.
If the item is the beginning of a blob, then item.chunkIndex is either 0 or 0x80. The first bit is used for integrity checking, while writing different chunks of a blob, basically. The function obviously doesn't consider that.

I created a patch which fixes that behavior and shows the formerly missing items on your partition (thanks again for uploading!). Our unit tests all pass on this change, so it shouldn't have any side effects. Please let us know if it works. We'll feed the change into our internal CI system but until it's deployed and back ported to version 4.0, it may take a few weeks.

0001-NVS-bugfix-iterator-skipping-version-1-blobs.zip

[alyf80]

Thanks @0xjakob, I can confirm that the patch solves the problem.

I'll leave this open as the change isn't merged yet.

[0xjakob]

@alyf80 Great to hear. It should be closed automatically once the change got merged.

[0xjakob]

@alyf80 The fix has just been merged to master, backports for the other versions including v4.0 will be available soon.