Move repeated NVS partition encryped to debug logs (IDFGH-14702)

[dizcza]

This should be a debug log

esp-idf/components/nvs_flash/src/nvs_api.cpp

Line 157 in c71d74e

ESP_LOGI(TAG, "NVS partition \"%s\" is encrypted.", NVS_DEFAULT_PART_NAME);

Firstly, I thought the log indicates there was an error to read/write from the enrypted nvs partition and the error was printed silently. I needed to find the source line to investigate whether it was just a notification or more.

[rrtandler]

Hi @dizcza,
The three IDF examples related to flash/NVS security:

• examples/security/flash_encryption/README.md
• examples/security/nvs_encryption_hmac/README.md
• examples/security/security_features_app/README.md

Are showing this information message in their respective log examples. Therefore the existence of the log Info message shouldn't be a surprise, rather confirmation of good flow. I would not consider emitting of this information using LOGI as a bug.

[dizcza]

I don't want to see the "NVS partition "%s" is encrypted" log each time I do a write operation.

[dizcza]

But I'm not insisting.
Feel free to close.

[rrtandler]

Hi @dizcza,
Are you using some framework for your application or is the NVS initialisation fully under control of your code? If your application is controlling the moment, when the NVS gets initialised, you can avoid it before every write. Once initialised, it can be reused. You can force the re-initialising of NVS only in case the nvs_get or nvs_set returns error codes. It may not only reduce the unwanted log message but also some cpu time.

[dizcza]

I don't use any frameworks for NVS operations - it's fully under my control. Except the cause that I'm using ESP-IDF + Arduino as a component.

esp_err_t bsp_nvs_flash_init() {
    esp_err_t err = nvs_flash_init();
    if (err == ESP_ERR_NVS_NO_FREE_PAGES || err == ESP_ERR_NVS_NEW_VERSION_FOUND) {
        // NVS partition was truncated and needs to be erased
        // Retry nvs_flash_init
        nvs_flash_erase();
        err = nvs_flash_init();
    }
    return err;
}

...
        nvs_handle_t nvs_handle = 0;
        if (bsp_nvs_flash_init() == ESP_OK) {
            if (nvs_open("gps", NVS_READWRITE, &nvs_handle) == ESP_OK) {
                nvs_set_u16(nvs_handle, "accuracy", accuracy_cm);
                nvs_close(nvs_handle);
            }
        }

So I call nvs_flash_init every time I do a write or read operation. I assume, nvs_flash_init does nothing if the requested NVS partition is already initialized. I came to this conclusion because the app works fine calling nvs_flash_init multiple times without destroying it and releasing the resources.

Is my assumption incorrect?

[rrtandler]

@dizcza - Yes, your assumption is correct. The secure init returns at the moment it detects already initialised partition (in your case the default one). While it, unfortunately, always emits the unwanted LOGI message. There is one fast solution for you - to keep track of initialisation at the function bsp_nvs_flash_init level i.e. in a static variable and omit the multiple call to the nvs_flash_init.
The long term solution will be the change from LOGI to LOGD in IDF.
I can also recommend to evaluate the esp_err_t result of nvs_set_u16 as it may return result codes valuable for required space estimation or need for re-initialisation. You can encounter errors like ESP_ERR_NVS_NOT_ENOUGH_SPACE, ESP_ERR_NVS_NOT_INITIALIZED or ESP_ERR_INVALID_STATE.

[dizcza]

All right, thanks for the clarification.

I'll go with your first approach suggestion.