NVS - what am I missing?

ndjurov
Posts: 65
Joined: Wed Mar 25, 2020 11:34 pm

NVS - what am I missing?

Postby ndjurov » Tue Mar 02, 2021 4:52 am

This is the first time I'm trying to work with the ESP32 NVS and I have a problem after writing just a few lines of code.
Just for the sake of testing - the first thing I do in the app_main(), is to initialize the NVS and then I'm trying to read a string value which certainly shouldn't exist as this is the very first time I'm accessing the NVS. If the nvs_get_str() fails (as it should), I call nvs_set_str() to set(for the first time) the value "Value1" for the "Tag1" key.
Sounds simple. However, the first time I call Get - it somehow reads correct value??? Before "Set" was ever called.
Here are the few lines from the log.
...
NVS partition found.
NVS partition namespace NVS_Test opened.
Get str returns 0.
NVS key Tag1 found. Value = Value1, size = 7
...
Note: there is no "NVS commit OK" line in the log at all.

I would really appreciate if you can shed some light on this issue.
Thanks a lot.

Here is the code:

Code: Select all

void app_main()
{
  esp_err_t ret;

  // Initialize NVS
  ret = nvs_flash_init();
  if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) 
  {
      ESP_ERROR_CHECK(nvs_flash_erase());
      ret = nvs_flash_init();
  }
  ESP_ERROR_CHECK( ret );
  if (ret == ESP_OK)
  {
    const esp_partition_t* nvs_partition = 
      esp_partition_find_first(ESP_PARTITION_TYPE_DATA, ESP_PARTITION_SUBTYPE_DATA_NVS, NULL);

    if(!nvs_partition)
      printf("FATAL ERROR: No NVS partition found\n");  
    else
    {
      printf("NVS partition found.\n");

      // open the partition in RW mode
      if (nvs_open("NVS_Test", NVS_READWRITE, &my_handle) == ESP_OK)
      {
        size_t required_size = 0;

        printf("NVS partition namespace NVS_Test opened.\n");
        ret = nvs_get_str(my_handle, "Tag1", NULL, &required_size);
        printf("Get str returns %d.\n", ret);
        if (ret == ESP_OK)
        {
          char* valueStr = malloc(required_size);
          if (nvs_get_str(my_handle, "Tag1", valueStr, &required_size) == ESP_OK)
            printf("NVS key Tag1 found. Value = %s, size = %d\n", valueStr, required_size);
          else
            printf("Error getting NVS key with size %d.\n", required_size);
          free(valueStr);      
        }        
        else if (ret == ESP_ERR_NVS_NOT_FOUND)
        {
          const char tagValue[] = "Value1";

          printf("NVS Tag1 key not found.\n");
          // This key was not found in the "NVS_Test" namespace. 
          // Could be the first time we are using it, so create the key-value pair:
          if (nvs_set_str(my_handle, "Tag1", tagValue) == ESP_OK)
          {
            printf("NVS key Tag1 created.\n");            
            if (nvs_commit(my_handle) == ESP_OK)
              printf("NVS commit OK.\n");
            else
              printf("NVS commit failed.\n");            
          }
          else
            printf("NVS set key failed.\n");          
        }

        nvs_close(my_handle);
      }    
    }        
  }

ESP_Sprite
Posts: 9746
Joined: Thu Nov 26, 2015 4:08 am

Re: NVS - what am I missing?

Postby ESP_Sprite » Tue Mar 02, 2021 5:51 am

Perhaps you played around with NVS before, and set that value? Reprogramming the ESP32 using 'idf.py flash' doesn't erase the NVS partition, as far as I know.

ndjurov
Posts: 65
Joined: Wed Mar 25, 2020 11:34 pm

Re: NVS - what am I missing?

Postby ndjurov » Tue Mar 02, 2021 3:22 pm

Thanks a lot ESP_Sprite, but this is my first attempt to use any NVS related ESP-IDF API. I still hope there is some logical explanation for this issue. There always is.

WiFive
Posts: 3529
Joined: Tue Dec 01, 2015 7:35 am

Re: NVS - what am I missing?

Postby WiFive » Tue Mar 02, 2021 4:02 pm

Best guess is that the board rebooted and ran the program once after reprogramming and you didn't see the log.

ndjurov
Posts: 65
Joined: Wed Mar 25, 2020 11:34 pm

Re: NVS - what am I missing?

Postby ndjurov » Tue Mar 02, 2021 10:44 pm

Here is another manifestation of this issue.
In order to further test the original issue, I made some small changes to the code.
Please don't pay too much attention to the "if (true)" as I used it just for testing.
Here is the code:

Code: Select all

void app_main()
{
  esp_err_t ret;

  // Initialize NVS
  ret = nvs_flash_init();
  if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) 
  {
      ESP_ERROR_CHECK(nvs_flash_erase());
      ret = nvs_flash_init();
  }
  ESP_ERROR_CHECK( ret );
  if (ret == ESP_OK)
  {
    const esp_partition_t* nvs_partition = 
      esp_partition_find_first(ESP_PARTITION_TYPE_DATA, ESP_PARTITION_SUBTYPE_DATA_NVS, NULL);

    if(!nvs_partition)
      printf("FATAL ERROR: No NVS partition found\n");  
    else
    {
      printf("NVS partition found.\n");

      // formating partition:
      if (true)
      {
        printf("Erasing NVS partition.\n");
        ret = (esp_partition_erase_range(nvs_partition, 0, nvs_partition->size));
        if(ret != ESP_OK) 
          printf("FATAL ERROR: Unable to erase the partition\n");
      }
      if (true)
      {
        // open the partition in RW mode
        if (nvs_open("NVS_Test", NVS_READWRITE, &my_handle) == ESP_OK)
        {
          size_t required_size = 0;

          printf("NVS partition namespace NVS_Test opened.\n");
          ret = nvs_get_str(my_handle, "Tag3", NULL, &required_size);
          printf("Get str returns %d.\n", ret);
          if (ret == ESP_OK)
          {
            char* valueStr = malloc(required_size);
            const char tagValue[] = "Value4";

            if (nvs_get_str(my_handle, "Tag3", valueStr, &required_size) == ESP_OK)
              printf("NVS key Tag3 found. Value = %s, size = %d\n", valueStr, required_size);
            else
              printf("Error getting NVS key with size %d.\n", required_size);
            free(valueStr); 
            printf("Setting new value.\n");
            if (nvs_set_str(my_handle, "Tag3", tagValue) == ESP_OK)
            {
              printf("NVS key Tag3 set to %s.\n", tagValue);            
              if (nvs_commit(my_handle) == ESP_OK)
                printf("NVS commit OK.\n");
              else
                printf("NVS commit failed.\n");
            }
          }        
          else if (ret == ESP_ERR_NVS_NOT_FOUND)
          {
            const char tagValue[] = "NewValue";

            printf("NVS Tag3 key not found.\n");
            // This key was not found in the "NVS_Test" namespace. 
            // Could be the first time we are using it, so create the key-value pair:
            if (nvs_set_str(my_handle, "Tag3", tagValue) == ESP_OK)
            {
              printf("NVS key Tag3 created.\n");            
              if (nvs_commit(my_handle) == ESP_OK)
                printf("NVS commit OK.\n");
              else
                printf("NVS commit failed.\n");            
            }
            else
              printf("NVS set key failed.\n");          
          }

          nvs_close(my_handle);
        }
      }   
    }        
  }
First I made a build where onlythe first blosk - esp_partition_erase_range() was enabled and got only these two (expected) lines in the log:
...
NVS partition found.
Erasing NVS partition.
...

After that I disabled the erasing block and enabled the second - get/set one and made and run another build. Of course, I expected that the NVS is now completely empty. However, I got these lines:
...
NVS partition found.
NVS partition namespace NVS_Test opened.
Get str returns 0.
NVS key Tag3 found. Value = NewValue, size = 9
Setting new value.
NVS key Tag3 set to Value4.
NVS commit OK.
...

Finally, I enabled both blocks, run that build and got the expected result:

...
NVS partition found.
Erasing NVS partition.
NVS partition namespace NVS_Test opened.
Get str returns 4354.
NVS Tag3 key not found.
NVS key Tag3 created.
NVS commit OK.
...

So, the only possible way this happens is that, just like WiFive suggested, the application somehow restarted by itself and didn't leave any trace of the restart (at least there is nothing in the VS Code terminal that indicates the restart).
Can anybody think of any reason for something like that happening? Can you think of a reliable way of testing whether this is what really happens?

Thanks a lot.

WiFive
Posts: 3529
Joined: Tue Dec 01, 2015 7:35 am

Re: NVS - what am I missing?

Postby WiFive » Tue Mar 02, 2021 10:47 pm

Hook up an LED and turn it on when the program runs.

boarchuz
Posts: 606
Joined: Tue Aug 21, 2018 5:28 am

Re: NVS - what am I missing?

Postby boarchuz » Tue Mar 02, 2021 10:52 pm

You can hold GPIO0 low (hold the BOOT button or similar) while it's flashing.

When the flash process completes and reboots, the ESP32 will go into download mode again rather than briefly running the app. Then manually reset once monitor is up.

ndjurov
Posts: 65
Joined: Wed Mar 25, 2020 11:34 pm

Re: NVS - what am I missing?

Postby ndjurov » Tue Mar 02, 2021 10:53 pm

Thanks WiFive,
How would you know that it's the first run that turned the LED on, not the second one. I guess it all happens within just a few milliseconds.

ndjurov
Posts: 65
Joined: Wed Mar 25, 2020 11:34 pm

Re: NVS - what am I missing?

Postby ndjurov » Tue Mar 02, 2021 10:56 pm

Thanks boarchuz,
I'll try that easy test and report back.
Still, any idea why would the application restart like that? Is this a common issue with ESP32 that has to be kept in mind when programming it?

boarchuz
Posts: 606
Joined: Tue Aug 21, 2018 5:28 am

Re: NVS - what am I missing?

Postby boarchuz » Tue Mar 02, 2021 10:59 pm

ndjurov wrote:
Tue Mar 02, 2021 10:56 pm
Still, any idea why would the application restart like that?
There's an option under "Serial flasher config", default "Reset after flashing". I guess it's pretty rare that it has any lasting effect after the subsequent reset so nobody notices?

Who is online

Users browsing this forum: No registered users and 90 guests