Merge branch 'bugfix/nvs_write_failure' into 'master'

Fix spi_flash_write regression and nvs error recovery

In the previous set of changes related to spi_flash, new alignment checks were added. One of these checks, word alignment of `src` buffer in `nvs_flas_write`, was unnecessary.  ROM `SPIWrite` function can handle unaligned source buffers.

This change caused an error to be returned to nvs for some legitimate write operations. Due to a bug in nvs, further write operations were possible, while the internal state of `Page` instance was broken. In WiFi functional tests, this inflicted havoc on the nvs partition, creating multiple duplicate items in the affected page. Because multiple duplicate items per page were never supposed to be handled during page load, duplicates were not removed. Thankfully this caused an assert at a later point in the loading process, otherwise this bug would be very difficult to detect.

This change set fixes the original spi_flash regression, handling of `INVALID` state of `nvs::Page`, and handling of duplicate items.

See merge request !161

components/nvs_flash/src/nvs_page.cpp

@@ -3,7 +3,7 @@
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
 // You may obtain a copy of the License at
-
+//
 //     http://www.apache.org/licenses/LICENSE-2.0
 //
 // Unless required by applicable law or agreed to in writing, software
@@ -131,8 +131,12 @@ esp_err_t Page::writeEntryData(const uint8_t* data, size_t size)
 esp_err_t Page::writeItem(uint8_t nsIndex, ItemType datatype, const char* key, const void* data, size_t dataSize)
 {
     Item item;
-
     esp_err_t err;
+    
+    if (mState == PageState::INVALID) {
+        return ESP_ERR_NVS_INVALID_STATE;
+    }
+    
     if (mState == PageState::UNINITIALIZED) {
         err = initialize();
         if (err != ESP_OK) {
@@ -166,7 +170,6 @@ esp_err_t Page::writeItem(uint8_t nsIndex, ItemType datatype, const char* key, c
     }
 
     // write first item
-
     size_t span = (totalSize + ENTRY_SIZE - 1) / ENTRY_SIZE;
     item = Item(nsIndex, datatype, span, key);
     mHashList.insert(item, mNextFreeEntry);
@@ -215,6 +218,11 @@ esp_err_t Page::readItem(uint8_t nsIndex, ItemType datatype, const char* key, vo
 {
     size_t index = 0;
     Item item;
+    
+    if (mState == PageState::INVALID) {
+        return ESP_ERR_NVS_INVALID_STATE;
+    }
+    
     esp_err_t rc = findItem(nsIndex, datatype, key, index, item);
     if (rc != ESP_OK) {
         return rc;
@@ -293,6 +301,8 @@ esp_err_t Page::eraseEntryAndSpan(size_t index)
         }
         if (item.calculateCrc32() != item.crc32) {
             rc = alterEntryState(index, EntryState::ERASED);
+            --mUsedEntryCount;
+            ++mErasedEntryCount;
             if (rc != ESP_OK) {
                 return rc;
             }
@@ -465,7 +475,9 @@ esp_err_t Page::mLoadEntryTable()
         if (end > ENTRY_COUNT) {
             end = ENTRY_COUNT;
         }
-        for (size_t i = 0; i < end; ++i) {
+        size_t span;
+        for (size_t i = 0; i < end; i += span) {
+            span = 1;
             if (mEntryTable.get(i) == EntryState::ERASED) {
                 lastItemIndex = INVALID_ENTRY;
                 continue;
@@ -479,6 +491,11 @@ esp_err_t Page::mLoadEntryTable()
                 return err;
             }
             
+            mHashList.insert(item, i);
+            
+            // search for potential duplicate item
+            size_t duplicateIndex = mHashList.find(0, item);
+
             if (item.crc32 != item.calculateCrc32()) {
                 err = eraseEntryAndSpan(i);
                 if (err != ESP_OK) {
@@ -488,25 +505,26 @@ esp_err_t Page::mLoadEntryTable()
                 continue;
             }
 
-            mHashList.insert(item, i);
             
-            if (item.datatype != ItemType::BLOB && item.datatype != ItemType::SZ) {
-                continue;
-            }
-
-            size_t span = item.span;
-            bool needErase = false;
-            for (size_t j = i; j < i + span; ++j) {
-                if (mEntryTable.get(j) != EntryState::WRITTEN) {
-                    needErase = true;
-                    lastItemIndex = INVALID_ENTRY;
-                    break;
+            if (item.datatype == ItemType::BLOB || item.datatype == ItemType::SZ) {
+                span = item.span;
+                bool needErase = false;
+                for (size_t j = i; j < i + span; ++j) {
+                    if (mEntryTable.get(j) != EntryState::WRITTEN) {
+                        needErase = true;
+                        lastItemIndex = INVALID_ENTRY;
+                        break;
+                    }
+                }
+                if (needErase) {
+                    eraseEntryAndSpan(i);
+                    continue;
                 }
             }
-            if (needErase) {
-                eraseEntryAndSpan(i);
+            
+            if (duplicateIndex < i) {
+                eraseEntryAndSpan(duplicateIndex);
             }
-            i += span - 1;
         }
 
         // check that last item is not duplicate
@@ -785,8 +803,12 @@ void Page::debugDump() const
             Item item;
             readEntry(i, item);
             if (skip == 0) {
-                printf("W ns=%2u type=%2u span=%3u key=\"%s\"\n", item.nsIndex, static_cast<unsigned>(item.datatype), item.span, item.key);
-                skip = item.span - 1;
+                printf("W ns=%2u type=%2u span=%3u key=\"%s\" len=%d\n", item.nsIndex, static_cast<unsigned>(item.datatype), item.span, item.key, (item.span != 1)?((int)item.varLength.dataSize):-1);
+                if (item.span > 0 && item.span <= ENTRY_COUNT - i) {
+                    skip = item.span - 1;
+                } else {
+                    skip = 0;
+                }
             } else {
                 printf("D\n");
                 skip--;

components/nvs_flash/test/crc.cpp

@@ -14,25 +14,51 @@
 #include <stdint.h>
 #include <stdbool.h>
 
-extern "C" unsigned long crc32_le(unsigned long crc_in, unsigned char const* data, unsigned int length)
-{
-    uint32_t i;
-    bool bit;
-    uint8_t c;
-    uint32_t crc = (uint32_t) crc_in;
+static const unsigned int crc32_le_table[256] = {
+    0x00000000L, 0x77073096L, 0xee0e612cL, 0x990951baL, 0x076dc419L, 0x706af48fL, 0xe963a535L, 0x9e6495a3L,
+    0x0edb8832L, 0x79dcb8a4L, 0xe0d5e91eL, 0x97d2d988L, 0x09b64c2bL, 0x7eb17cbdL, 0xe7b82d07L, 0x90bf1d91L,
+    0x1db71064L, 0x6ab020f2L, 0xf3b97148L, 0x84be41deL, 0x1adad47dL, 0x6ddde4ebL, 0xf4d4b551L, 0x83d385c7L,
+    0x136c9856L, 0x646ba8c0L, 0xfd62f97aL, 0x8a65c9ecL, 0x14015c4fL, 0x63066cd9L, 0xfa0f3d63L, 0x8d080df5L,
+    0x3b6e20c8L, 0x4c69105eL, 0xd56041e4L, 0xa2677172L, 0x3c03e4d1L, 0x4b04d447L, 0xd20d85fdL, 0xa50ab56bL,
+    0x35b5a8faL, 0x42b2986cL, 0xdbbbc9d6L, 0xacbcf940L, 0x32d86ce3L, 0x45df5c75L, 0xdcd60dcfL, 0xabd13d59L,
+    0x26d930acL, 0x51de003aL, 0xc8d75180L, 0xbfd06116L, 0x21b4f4b5L, 0x56b3c423L, 0xcfba9599L, 0xb8bda50fL,
+    0x2802b89eL, 0x5f058808L, 0xc60cd9b2L, 0xb10be924L, 0x2f6f7c87L, 0x58684c11L, 0xc1611dabL, 0xb6662d3dL,
+    0x76dc4190L, 0x01db7106L, 0x98d220bcL, 0xefd5102aL, 0x71b18589L, 0x06b6b51fL, 0x9fbfe4a5L, 0xe8b8d433L,
+    0x7807c9a2L, 0x0f00f934L, 0x9609a88eL, 0xe10e9818L, 0x7f6a0dbbL, 0x086d3d2dL, 0x91646c97L, 0xe6635c01L,
+    0x6b6b51f4L, 0x1c6c6162L, 0x856530d8L, 0xf262004eL, 0x6c0695edL, 0x1b01a57bL, 0x8208f4c1L, 0xf50fc457L,
+    0x65b0d9c6L, 0x12b7e950L, 0x8bbeb8eaL, 0xfcb9887cL, 0x62dd1ddfL, 0x15da2d49L, 0x8cd37cf3L, 0xfbd44c65L,
+    0x4db26158L, 0x3ab551ceL, 0xa3bc0074L, 0xd4bb30e2L, 0x4adfa541L, 0x3dd895d7L, 0xa4d1c46dL, 0xd3d6f4fbL,
+    0x4369e96aL, 0x346ed9fcL, 0xad678846L, 0xda60b8d0L, 0x44042d73L, 0x33031de5L, 0xaa0a4c5fL, 0xdd0d7cc9L,
+    0x5005713cL, 0x270241aaL, 0xbe0b1010L, 0xc90c2086L, 0x5768b525L, 0x206f85b3L, 0xb966d409L, 0xce61e49fL,
+    0x5edef90eL, 0x29d9c998L, 0xb0d09822L, 0xc7d7a8b4L, 0x59b33d17L, 0x2eb40d81L, 0xb7bd5c3bL, 0xc0ba6cadL,
     
-    while (length--) {
-        c = *data++;
-        for (i = 0x80; i > 0; i >>= 1) {
-            bit = crc & 0x80000000;
-            if (c & i) {
-                bit = !bit;
-            }
-            crc <<= 1;
-            if (bit) {
-                crc ^= 0x04c11db7;
-            }
-        }
+    0xedb88320L, 0x9abfb3b6L, 0x03b6e20cL, 0x74b1d29aL, 0xead54739L, 0x9dd277afL, 0x04db2615L, 0x73dc1683L,
+    0xe3630b12L, 0x94643b84L, 0x0d6d6a3eL, 0x7a6a5aa8L, 0xe40ecf0bL, 0x9309ff9dL, 0x0a00ae27L, 0x7d079eb1L,
+    0xf00f9344L, 0x8708a3d2L, 0x1e01f268L, 0x6906c2feL, 0xf762575dL, 0x806567cbL, 0x196c3671L, 0x6e6b06e7L,
+    0xfed41b76L, 0x89d32be0L, 0x10da7a5aL, 0x67dd4accL, 0xf9b9df6fL, 0x8ebeeff9L, 0x17b7be43L, 0x60b08ed5L,
+    0xd6d6a3e8L, 0xa1d1937eL, 0x38d8c2c4L, 0x4fdff252L, 0xd1bb67f1L, 0xa6bc5767L, 0x3fb506ddL, 0x48b2364bL,
+    0xd80d2bdaL, 0xaf0a1b4cL, 0x36034af6L, 0x41047a60L, 0xdf60efc3L, 0xa867df55L, 0x316e8eefL, 0x4669be79L,
+    0xcb61b38cL, 0xbc66831aL, 0x256fd2a0L, 0x5268e236L, 0xcc0c7795L, 0xbb0b4703L, 0x220216b9L, 0x5505262fL,
+    0xc5ba3bbeL, 0xb2bd0b28L, 0x2bb45a92L, 0x5cb36a04L, 0xc2d7ffa7L, 0xb5d0cf31L, 0x2cd99e8bL, 0x5bdeae1dL,
+    0x9b64c2b0L, 0xec63f226L, 0x756aa39cL, 0x026d930aL, 0x9c0906a9L, 0xeb0e363fL, 0x72076785L, 0x05005713L,
+    0x95bf4a82L, 0xe2b87a14L, 0x7bb12baeL, 0x0cb61b38L, 0x92d28e9bL, 0xe5d5be0dL, 0x7cdcefb7L, 0x0bdbdf21L,
+    0x86d3d2d4L, 0xf1d4e242L, 0x68ddb3f8L, 0x1fda836eL, 0x81be16cdL, 0xf6b9265bL, 0x6fb077e1L, 0x18b74777L,
+    0x88085ae6L, 0xff0f6a70L, 0x66063bcaL, 0x11010b5cL, 0x8f659effL, 0xf862ae69L, 0x616bffd3L, 0x166ccf45L,
+    0xa00ae278L, 0xd70dd2eeL, 0x4e048354L, 0x3903b3c2L, 0xa7672661L, 0xd06016f7L, 0x4969474dL, 0x3e6e77dbL,
+    0xaed16a4aL, 0xd9d65adcL, 0x40df0b66L, 0x37d83bf0L, 0xa9bcae53L, 0xdebb9ec5L, 0x47b2cf7fL, 0x30b5ffe9L,
+    0xbdbdf21cL, 0xcabac28aL, 0x53b39330L, 0x24b4a3a6L, 0xbad03605L, 0xcdd70693L, 0x54de5729L, 0x23d967bfL,
+    0xb3667a2eL, 0xc4614ab8L, 0x5d681b02L, 0x2a6f2b94L, 0xb40bbe37L, 0xc30c8ea1L, 0x5a05df1bL, 0x2d02ef8dL
+};
+
+
+
+extern "C" unsigned int crc32_le(unsigned int crc, unsigned char const * buf,unsigned int len)
+{
+    unsigned int i;
+    crc = ~crc;
+    for(i=0;i<len;i++){
+        crc = crc32_le_table[(crc^buf[i])&0xff]^(crc>>8);
     }
-    return crc;
+    return ~crc;
 }
+

components/nvs_flash/test/spi_flash_emulation.h

@@ -74,11 +74,11 @@ public:
             return false;
         }
         
-        if (mFailCountdown != SIZE_MAX && mFailCountdown-- == 0) {
-            return false;
-        }
-
         for (size_t i = 0; i < size / 4; ++i) {
+            if (mFailCountdown != SIZE_MAX && mFailCountdown-- == 0) {
+                return false;
+            }
+
             uint32_t sv = src[i];
             size_t pos = dstAddr / 4 + i;
             uint32_t& dv = mData[pos];
@@ -142,6 +142,18 @@ public:
         return reinterpret_cast<const uint8_t*>(mData.data());
     }
     
+    void load(const char* filename)
+    {
+        FILE* f = fopen(filename, "rb");
+        fseek(f, 0, SEEK_END);
+        off_t size = ftell(f);
+        assert(size % SPI_FLASH_SEC_SIZE == 0);
+        mData.resize(size);
+        fseek(f, 0, SEEK_SET);
+        auto s = fread(mData.data(), SPI_FLASH_SEC_SIZE, size / SPI_FLASH_SEC_SIZE, f);
+        assert(s == static_cast<size_t>(size / SPI_FLASH_SEC_SIZE));
+    }
+
     void clearStats()
     {
         mReadBytes = 0;

components/nvs_flash/test/test_nvs.cpp

@@ -894,7 +894,7 @@ TEST_CASE("test recovery from sudden poweroff", "[.][long][nvs][recovery][monkey
     
     size_t totalOps = 0;
     int lastPercent = -1;
-    for (uint32_t errDelay = 4; ; ++errDelay) {
+    for (uint32_t errDelay = 0; ; ++errDelay) {
         INFO(errDelay);
         emu.randomize(seed);
         emu.clearStats();
@@ -903,23 +903,25 @@ TEST_CASE("test recovery from sudden poweroff", "[.][long][nvs][recovery][monkey
         
         if (totalOps != 0) {
             int percent = errDelay * 100 / totalOps;
-            if (percent != lastPercent) {
+            if (percent > lastPercent) {
                 printf("%d/%d (%d%%)\r\n", errDelay, static_cast<int>(totalOps), percent);
                 lastPercent = percent;
             }
         }
         
-        TEST_ESP_OK(nvs_flash_init_custom(NVS_FLASH_SECTOR, NVS_FLASH_SECTOR_COUNT_MIN));
 
         nvs_handle handle;
-        TEST_ESP_OK(nvs_open("namespace1", NVS_READWRITE, &handle));
-        
         size_t count = iter_count;
-        if(test.doRandomThings(handle, gen, count) != ESP_ERR_FLASH_OP_FAIL) {
-            nvs_close(handle);
-            break;
+
+        if (nvs_flash_init_custom(NVS_FLASH_SECTOR, NVS_FLASH_SECTOR_COUNT_MIN) == ESP_OK) {
+            if (nvs_open("namespace1", NVS_READWRITE, &handle) == ESP_OK) {
+                if(test.doRandomThings(handle, gen, count) != ESP_ERR_FLASH_OP_FAIL) {
+                    nvs_close(handle);
+                    break;
+                }
+                nvs_close(handle);
+            }
         }
-        nvs_close(handle);
         
         TEST_ESP_OK(nvs_flash_init_custom(NVS_FLASH_SECTOR, NVS_FLASH_SECTOR_COUNT_MIN));
         TEST_ESP_OK(nvs_open("namespace1", NVS_READWRITE, &handle));
@@ -929,7 +931,7 @@ TEST_CASE("test recovery from sudden poweroff", "[.][long][nvs][recovery][monkey
             CHECK(0);
         }
         nvs_close(handle);
-        totalOps = emu.getEraseOps() + emu.getWriteOps();
+        totalOps = emu.getEraseOps() + emu.getWriteBytes() / 4;
     }
 }
 
@@ -951,6 +953,108 @@ TEST_CASE("test for memory leaks in open/set", "[leaks]")
     }
 }
 
+TEST_CASE("duplicate items are removed", "[nvs][dupes]")
+{
+    SpiFlashEmulator emu(3);
+    {
+        // create one item
+        nvs::Page p;
+        p.load(0);
+        p.writeItem<uint8_t>(1, "opmode", 3);
+    }
+    {
+        // add another two without deleting the first one
+        nvs::Item item(1, ItemType::U8, 1, "opmode");
+        item.data[0] = 2;
+        item.crc32 = item.calculateCrc32();
+        emu.write(3 * 32, reinterpret_cast<const uint32_t*>(&item), sizeof(item));
+        emu.write(4 * 32, reinterpret_cast<const uint32_t*>(&item), sizeof(item));
+        uint32_t mask = 0xFFFFFFEA;
+        emu.write(32, &mask, 4);
+    }
+    {
+        // load page and check that second item persists
+        nvs::Storage s;
+        s.init(0, 3);
+        uint8_t val;
+        ESP_ERROR_CHECK(s.readItem(1, "opmode", val));
+        CHECK(val == 2);
+    }
+    {
+        Page p;
+        p.load(0);
+        CHECK(p.getErasedEntryCount() == 2);
+        CHECK(p.getUsedEntryCount() == 1);
+    }
+}
+
+TEST_CASE("recovery after failure to write data", "[nvs]")
+{
+    SpiFlashEmulator emu(3);
+    const char str[] = "value 0123456789abcdef012345678value 0123456789abcdef012345678";
+
+    // make flash write fail exactly in Page::writeEntryData
+    emu.failAfter(17);
+    {
+        Storage storage;
+        TEST_ESP_OK(storage.init(0, 3));
+        
+        TEST_ESP_ERR(storage.writeItem(1, ItemType::SZ, "key", str, strlen(str)), ESP_ERR_FLASH_OP_FAIL);
+        
+        // check that repeated operations cause an error
+        TEST_ESP_ERR(storage.writeItem(1, ItemType::SZ, "key", str, strlen(str)), ESP_ERR_NVS_INVALID_STATE);
+        
+        uint8_t val;
+        TEST_ESP_ERR(storage.readItem(1, ItemType::U8, "key", &val, sizeof(val)), ESP_ERR_NVS_NOT_FOUND);
+    }
+    {
+        // load page and check that data was erased
+        Page p;
+        p.load(0);
+        CHECK(p.getErasedEntryCount() == 3);
+        CHECK(p.getUsedEntryCount() == 0);
+        
+        // try to write again
+        TEST_ESP_OK(p.writeItem(1, ItemType::SZ, "key", str, strlen(str)));
+    }
+}
+
+TEST_CASE("crc error in variable length item is handled", "[nvs]")
+{
+    SpiFlashEmulator emu(3);
+    const uint64_t before_val = 0xbef04e;
+    const uint64_t after_val = 0xaf7e4;
+    // write some data
+    {
+        Page p;
+        p.load(0);
+        TEST_ESP_OK(p.writeItem<uint64_t>(0, "before", before_val));
+        const char* str = "foobar";
+        TEST_ESP_OK(p.writeItem(0, ItemType::SZ, "key", str, strlen(str)));
+        TEST_ESP_OK(p.writeItem<uint64_t>(0, "after", after_val));
+    }
+    // corrupt some data
+    uint32_t w;
+    CHECK(emu.read(&w, 32 * 3 + 8, sizeof(w)));
+    w &= 0xf000000f;
+    CHECK(emu.write(32 * 3 + 8, &w, sizeof(w)));
+    // load and check
+    {
+        Page p;
+        p.load(0);
+        CHECK(p.getUsedEntryCount() == 2);
+        CHECK(p.getErasedEntryCount() == 2);
+
+        uint64_t val;
+        TEST_ESP_OK(p.readItem<uint64_t>(0, "before", val));
+        CHECK(val == before_val);
+        TEST_ESP_ERR(p.findItem(0, ItemType::SZ, "key"), ESP_ERR_NVS_NOT_FOUND);
+        TEST_ESP_OK(p.readItem<uint64_t>(0, "after", val));
+        CHECK(val == after_val);
+    }
+}
+
+
 TEST_CASE("dump all performance data", "[nvs]")
 {
     std::cout << "====================" << std::endl << "Dumping benchmarks" << std::endl;

components/spi_flash/flash_ops.c

@@ -39,7 +39,7 @@ static spi_flash_counters_t s_flash_stats;
 #define COUNTER_STOP(counter)  \
     do{ \
         s_flash_stats.counter.count++; \
-        s_flash_stats.counter.time += (xthal_get_ccount() - ts_begin) / (XT_CLOCK_FREQ / 1000000); \\
+        s_flash_stats.counter.time += (xthal_get_ccount() - ts_begin) / (XT_CLOCK_FREQ / 1000000); \
     } while(0)
 
 #define COUNTER_ADD_BYTES(counter, size) \
@@ -126,10 +126,6 @@ esp_err_t IRAM_ATTR spi_flash_erase_range(uint32_t start_addr, uint32_t size)
 
 esp_err_t IRAM_ATTR spi_flash_write(size_t dest_addr, const void *src, size_t size)
 {
-    // TODO: replace this check with code which deals with unaligned sources
-    if (((ptrdiff_t) src) % 4 != 0) {
-        return ESP_ERR_INVALID_ARG;
-    }
     // Destination alignment is also checked in ROM code, but we can give
     // better error code here
     // TODO: add handling of unaligned destinations

components/spi_flash/include/esp_spi_flash.h

@@ -74,7 +74,7 @@ esp_err_t spi_flash_erase_range(size_t start_addr, size_t size);
 /**
  * @brief  Write data to Flash.
  *
- * @note Both des_addr and src_addr have to be 4-byte aligned.
+ * @note Address in flash, dest, has to be 4-byte aligned.
  *       This is a temporary limitation which will be removed.
  *
  * @param  dest  destination address in Flash
@@ -88,7 +88,7 @@ esp_err_t spi_flash_write(size_t dest, const void *src, size_t size);
 /**
  * @brief  Read data from Flash.
  *
- * @note Both des_addr and src_addr have to be 4-byte aligned.
+ * @note Both src and dest have to be 4-byte aligned.
  *       This is a temporary limitation which will be removed.
  *
  * @param  src   source address of the data in Flash.