nvs_get_u32 keeps returning "ESP_ERR_NVS_NOT_FOUND"

[Zingemneire]

Hi,

I have run into a strange problem and was wondering if anyone has an idea or suggestion as to what is going wrong.
It is particularly strange as I had this working properly before. Below is a section of code, for readability reduced to the essential parts.

Code: Select all

   espError = nvs_open_from_partition( "ParameterPart", "Parameters", NVS_READWRITE, &nvsHandle );
   ...
   ..
   .
   espError = nvs_get_u32 ( nvsHandle, ParameterList [ ParameterDataVersion ].Key , ( uint32_t * ) ParameterList [ ParameterDataVersion ].PointerToRamdata );
   ESP_LOGI
   (
      TAG,
      "Read version result: handle=%d, key=%s, version=%d, espError=%d",
      nvsHandle,
      ParameterList [ ParameterDataVersion ].Key,
      *( uint32_t * ) ParameterList [ ParameterDataVersion ].PointerToRamdata,
      espError
   );
   ...
   ..
   .
   Pstor_SetAllStorageDatatoRamDefaults ( nvsHandle )
   ...
   ..
   .
   espError = nvs_set_u32 ( NvsHandle, key, *( uint32_t * ) dataLocation ); break;
   ...
   ..
   .
   ESP_LOGI
   (
      TAG,
      "Stored Parameter with NvsHandle %d, index %d, key=%s to flash",
      NvsHandle,
      i,
      key
   );

The first action is to nvs_open_from_partition for which the earlier nvs_flash_init_partition operation worked perfectly so both functions return ESP_OK as expected. The result is that I get an NVS handle for partition ParameterPart and namespace Parameters.
Next I try to read the parameters data version using nvs_get_u32 followed by an ESP_LOGI operation to see the result of that. The output from which is:

<ESC>[0;32mI (1174) ParameterStorage.c: Read version result: handle=1, key=ParDataVersion , version=0, espError=4354<ESC>[0m


The next action is to call Pstor_SetAllStorageDatatoRamDefaults which will set all flash data to the defined default values as set up in the parameters' RAM image.

Within that function I use nvs_set_32 to actually write the parameter version data to the flash, it is the very last parameter I set.
Once nvs_set_32 returns OK I execute the next ESP_LOGI operation. The output of which is:

<ESC>[0;32mI (2117) ParameterStorage.c: Stored Parameter with NvsHandle 1, index 0, key=ParDataVersion to flash<ESC>[0m

The output indicates that I am using the exact same handle as before, the same key etc...
To the best of my knowledge the fact that I am writing data using that same handle with the nvs_set_... functions should take care of writing the parameters into the correct partition and namespace and if necessary also create the namespace when the first parameter is written to it.

The first time I get espError=4354 (ESP_ERR_NVS_NOT_FOUND) is 100% logical: initially the namespace and key/value pair do not exist and must be created. What is not logical is that for each parameter I write to flash the various nvs_set_... functions always report ESP_OK. That indicates the write operations work but when I try to read back the parameter version at every next start I get the same ESP_ERR_NVS_NOT_FOUND error again, on and on and on.

PS: I did not forget to use nvs_commit when necessary !

[f.h-f.s.]

Try the examples: https://github.com/espressif/esp-idf/tr ... vs_rw_blob, https://github.com/espressif/esp-idf/tr ... s_rw_value. Do you get the same errors there? Do you call nvs_open/nvs_close?

[Zingemneire]

Hi f.h-f.s.

I tried those examples some time ago and no, I did not get those errors.

In the mean time I have done some more detailed testing and I have found some more weird things using a parameter data version test number of 0x5555AAAA ( decimal = 1431677610 )

(1) I have two locations in the program where it calls the nvs_get_u32 function to read that particular data item.
The first one is where I get the ESP_ERR_NVS_NOT_FOUND error message.
The second one is in another bit of test code to test the JSON code to retrieve some parameters.
To the list of parameters to retrieve I have added the parameter data version. To read it the software uses another function and in that function when the item being asked for is the parameter data version it will not provide the value in the RAM image of the parameter as it does with the other ones.
Instead it will specifically use the nvs_get_u32 function to read it from flash, if the response from that function is not ESP_OK it will modify the value read from flash to 0xFEFEFEFE instead of the expected 0x5555AAAA. Test result: it does not modify it.
Therefore when I use the exact same function to read the parameter version it does find the key/value pair and it must return ESP_OK to retain the 0x5555AAAA value read from flash.

(2) Having observed the way it works in (1) I decided to have a closer look at the output I get from the first ESP_LOGI operation. Sure enough: I am still getting the 4354 error which indicates it has not found the key/value but it equally sure enough comes up with the correct parameter data version number as you can see in this recorded output line:

<ESC>[0;32mI (1119) ParameterStorage.c: Read version result: handle=1, key=ParDataVersion , version=1431677610, espError=4354<ESC>[0m

The value of 0x5555AAAA does not just magically appear from thin air: the nvs_get_u32 function must have found the key/value pair and retrieved the value correctly from the flash whilst returning the incorrect "4354" error value, something it does not do any more when the other test code runs 2 seconds later.

It is a real mystery but at least I now have a workaround for it. It does sort of confirm though that when I did the complete parameter storage component testing a few weeks ago it could, and probably, did work correctly. I don't know what makes it behave differently now but the fact that it can work correctly after a few seconds tells me my observation then was most likely 100% correct.

[Zingemneire]

Hi,

I need to correct the last post: it does not find the key/value pair in the second case so the reported error 4354 is correct.
However, it absolutely does work correctly in the second case.

I will try running the same function with some retries to see if that makes any difference.

Update:
1) Nope, 100 retries over 2 seconds makes no difference
2) The test code does set the parameter data version value first via nvs_set_u32 before calling nvs_get_32 to retrieve the value later on. Both operations run like clockwork and return ESP_OK as they should.

[f.h-f.s.]

Also try a "make erase_flash" to start clean, and re-flash your program.

[Zingemneire]

Ok, good idea. I see the erase_flash happening but it does not make the slightest difference. Even "make erase_flash flash monitor" does not help.

That first attempt to read the value stored with key "ParDataVersion" simply does not work whereas storing and committing it, using the same key and handler, 800 microseconds later does work flawlessly. As does reading it a second or so later.

I have tried delaying the first call, calling it multiple times, preceding it with a "set" operation etc... none of it works.

It did work before as I have multiple log files where correct operation was registered from when I was doing full testing of the parameter storage component.

It is only know when I was working with somethings else that i noticed the parameters were always the default values at the start.

[Zingemneire]

New test:

this bit of silly code does work:

Code: Select all

   // fdtest test begin
   espError = nvs_set_u32 ( nvsHandle, ParameterList [ ParameterDataVersion ].Key , *( uint32_t * ) ParameterList [ ParameterDataVersion ].PointerToRamdata );
   ESP_LOGI ( TAG, "nvs_set_u32 with key %s result %d", ParameterList [ ParameterDataVersion ].Key, espError );
   // fdtest test end
   espError = nvs_get_u32 ( nvsHandle, ParameterList [ ParameterDataVersion ].Key , ( uint32_t * ) ParameterList [ ParameterDataVersion ].PointerToRamdata );

and it produces this output:

(623) ParameterStorage.c: nvs_set_u32 with key ParDataVersion result 0
(623) ParameterStorage.c: Read version result: handle=1, key=ParDataVersion , version=1431677610, espError=0

It defeats the entire purpose of having a version check but does prove that after a successful storage operation it is capable of finding the ParDataVersion key/value pair.
As this is a repetitive run with a deep sleep period in between each run and each run performs an equally successful storage of that key/value pair ( as shown below ), with the appropriate nvs_commit operation, I would expect the key/value pair to be available after a restart but it is not or it can't be found, not what I would expect from NVS storage.

The output below is what is recorded once the other storage operation using the nvs_set_u32 function returns ESP_OK

ParameterStorage.c: Stored Parameter with NvsHandle 1, index 0, key=ParDataVersion , value 5555AAAA to flash<ESC>[0m

[Zingemneire]

Hi,

I found a method to actually make it work but it is so daft I have a hard time believing it.

After detecting the ParDataVersion key/value pair is not there I call a function to copy all the values in the RAM image variables to flash but just before that I want to make sure the flash partition is clean so I had the following function to do that:

Code: Select all

espError = nvs_flash_erase_partition( ParameterPartition );

From earlier testing I did with similar NVS on some other partitions for measurement and event log storage I remembered that that function caused unexpected problems so I replaced it with this:

Code: Select all

nvs_erase_all( nvsHandle );

Guess what: now it works, as expected the ParDataVersion key/value pair is found missing once, the flash content is set to a copy of the RAM image variables content. When the ESP32-WROVE reboots the ParDataVersion key/value pair is found. the content is copied from flash to RAM and thins carry on as normal.

Ok, I am happy it works now but if anyone has a suggestion as to why I would be even happier.

[Zingemneire]

One more for the category: "glaringly obvious when pointed out".

Of course it does not work as it should, a call to nvs_flash_erase_partition must be followed by a call to nvs_flash_init_partition simply using it to clean a partition without doing so throws a spanner in the works !!!

Damn it, I really should have known.