SPIFFs File Corruption

[pnkowl]

Expected behavior

• file contents never change as a result of other file adds

Actual behavior

• files go missing
• files are truncated
• files are altered

Supplied cases show this occurs when all SPIFFs pages have been written once.
For a 4MB module, this usually takes awhile.

When no SPIFFs pages are free, but are either used or deleted, a garbage collection
operation must be performed to free the deleted pages. Sometimes this results in

• truncated files (overwritten pages)
• overwritten index or object lookup pages (data is there but filename page is gone)
• modified pages (data file bytes are changed at the beginning or end of a page boundary)

Test code

Provide a Minimal, Complete, and Verifiable example which will reproduce the problem.

image and file
esp8266_21_4M_06.bin  -- esp8266 4M image with SPIFFS okay, all that is important is SPIFFS layout
20200505_test009.txt  -- add this 32kbyte file to SPIFFS which then reveals an issue with SPIFFS garbage collection?
esp8266_21_4M_07.bin  -- resultant image with SPIFFS corruption

Basic process
1. flash "06" image to 4M esp8266
2. upload 32kbyte file to SPIFFS (FTP or serial, corrupts either way)
3. valid data is overwritten (see below for details)

NodeMCU startup banner

You MUST include the firmware startup banner to describe the version you are using. We reserve the right to immediately close any bug that doesn't.

Nodemcu-build.com provided by frightanic.com
branch: master
commit: 3d91785
release:
release DTS: 202002231746
SSL: false
build type: float
LFS: 0x40000
modules: adc,bit,cron,dht,enduser_setup,file,gpio,mqtt,net,node,ow,pwm2,rtcmem,rtctime,sntp,struct,tmr,uart,wifi
build 2020-05-01 13:41 powered by Lua 5.1.4 on SDK 3.0.1-dev(fce080e)

Hardware

Describe which ESP8266/ESP32 device you use and document any special hardware setup
required to reproduce the problem.

Wemos D1 mini (4MB), aka esp-21 ref. below
Nodemcu V0.9 (4MB), aka esp-01 ref. below

Other Resources Used

FTP
https://nodemcu.readthedocs.io/en/master/lua-modules/ftpserver/
with several added hooks
use default user and pwd: "test","12345"

Serial Interface Software
Lua Loader 0.91

Flasher, Unloader
esptool.py

Local LUA code
as listed below to help reveal issue but does not cause it

Detailed Notes

How to find the "issue" locations?
Find the 4 locations below with "-->" in the left margin.
This is where expectations do not match reality.

Setup Process

 1. flash LFS 256k firmware
    python c:\esptool\esptool.py -b 115200 --port COM5 write_flash --flash_freq 80m 0x000000 nodemcu-master-19-modules-2020-05-01-13-41-35-float.bin
 2. serial upload LFS image (e.g. lualoader)
    LFS200426a7.img   48449 bytes
 3. flash LFS
    =node.flashreload("LFS200426a7.img")
    LFS region updated.  Restarting.
 4. clean up SPIFFS
    =file.format()
 5. upload
    init_0.lua        1177 bytes
    ide_c_local.lua   677 bytes
    ide_wifi_cfg.lua   654 bytes
    LLbin.lua         639 bytes          -- by lualoader
 6. make a backup (image module)
    python c:\esptool\esptool.py -b 115200 --port COM5 read_flash 0x00000 0x400000 esp8266_21_4M_01.bin
 7. full boot for the first time
    dofile("init_0.lua")
    including webide, telnet, FTP support
 8. =file.fsinfo()
    3232629 4518    3237147
 9. FTP one at a time and create an image each time for later comparison
    1,048,576 20200505_test023.txt
    1,048,576 20200505_test006.txt
      327,680 20200505_test007.txt
      262,144 20200505_test008.txt
    files are arbitrarily big, but need to get to the end of SPIFFS (but not over)
10. =file.fsinfo()
    522833  2714314 3237147
11. backup module (high speed seems ok for reads, is repeatable).  This is the "known good SPIFFS state"
    python c:\esptool\esptool.py -b 921600 --port COM5 read_flash 0x00000 0x400000 esp8266_21_4M_06.bin

What we have at this point

 1. =file.fsinfo()
    522833 2714314 3237147
 2. Confirmed that very few free blocks are left in SPIFFS before first garbage collection is required to free deleted space
    last written page has offset  4141568
    last memory byte              4194304
 3. SPIFFS files all "echo" expected byte counts
    20200505_test006.txt   1048576 bytes
    20200505_test007.txt    327680 bytes
    20200505_test008.txt    262144 bytes
    20200505_test023.txt   1048576 bytes
    LLbin.lua                  639 bytes
    ide_c_local.lua            677 bytes
    ide_wifi_cfg.lua           654 bytes
    init_0.lua                1177 bytes

---

Corruption Process Steps for FTP

 1. FTP with FileZilla
    32,768 20200505_test009.txt
    Status: Starting upload of E:\IoT\ESP8266\NodeMCU\Modules and Functions\FTP\transfer rates\20200505_test009.txt
    Status: File transfer successful, transferred 32,768 bytes in 2 seconds
    As needed
    a. power up module
    b. modify ide_wifi_cfg.lua for your network (use serial interface, since 192.168.4.1 access not included in this image)
    c. dofile("init_0.lua") to start IDE
    d. use supplied IP for FTP connection
 2. =file.fsinfo()
    489450  2747697 323714
 3. check files for basic integrity
    function f(a) i=0; local src = file.open(a, "r"); if src then local line; repeat line = src:read(); if line then l=string.len(line); i=i+l; print(l,i); if(i>1953300) then print(line) end end until line == nil src:close(); src = nil end end
--> f("20200505_test006.txt")       *** file entry no longer exists, but file was not deleted by the user ***
    f("20200505_test023.txt")       ok
    f("20200505_test007.txt")       ok
    f("20200505_test008.txt")       ok
    f("20200505_test009.txt")       ok
 4. Investiage missing file
    many bits of data of the missing file exist repeating "19191919"
    1 page contains filename 20200505_test009.txt but apparently no longer valid (deleted?)
 5. backup module
    python c:\esptool\esptool.py -b 921600 --port COM5 read_flash 0x00000 0x400000 esp8266_21_4M_07.bin

---

Corruption process Steps for serial upload

 1. restore prior image
    python c:\esptool\esptool.py -b 115200 --port COM5 write_flash --flash_freq 80m 0x000000 esp8266_21_4M_06.bin
 2. upload file with lualoader
    32768 bytes uploaded to 20200505_test009.txt
 3. reported SPIFFS
    for k,v in pairs(file.list()) do l = string.format("%-15s",k) print(l.."   "..v.." bytes") end
    20200505_test006.txt   1048576 bytes
    20200505_test007.txt   327680 bytes
    20200505_test008.txt   262144 bytes
    20200505_test009.txt   32768 bytes
    20200505_test023.txt   1048576 bytes
    LLbin.lua         639 bytes
    ide_c_local.lua   677 bytes
    ide_wifi_cfg.lua   654 bytes
    init_0.lua        1177 bytes
 4. Actual SPIFFS
    function f(a) i=0; local src = file.open(a, "r"); if src then local line; repeat line = src:read(); if line then l=string.len(line); i=i+l; print(l,i); if(i>1953300) then print(line) end end until line == nil src:close(); src = nil end end
    f("20200505_test006.txt")       1024    1048576
    f("20200505_test023.txt")       1024    1048576
    f("20200505_test007.txt")       1024    327680
    f("20200505_test008.txt")       1024    262144
--> f("20200505_test009.txt")       1024    8192       *** wrong, expected 32k bytes ***
    f("LLbin.lua")          639     639
    f("ide_c_local.lua")    677     677
    f("ide_wifi_cfg.lua")   654     654
    f("init_0.lua")         153     1177
 5. =file.fsinfo() * different than FTP case which really should not be
    494721  2742426 3237147
 6. image module
    python c:\esptool\esptool.py -b 921600 --port COM5 read_flash 0x00000 0x400000 esp8266_01_4M_13.bin

ESP-01 Tests

 1. restore image from ESP-21
    python c:\esptool\esptool.py -b 115200 --port COM5 write_flash --flash_freq 80m 0x000000 esp8266_21_4M_06.bin
 2. Similar results for repeated FTP case
 3. Similar results for repeated lualoader case
 4. image
    python c:\esptool\esptool.py -b 921600 --port COM5 read_flash 0x00000 0x400000 esp8266_01_4M_14.bin

---

File contents corruption

 1. lualoader cases corrupt the contents of init_0.lua
 2. Before/After page contents are over/under below
 3. Note: pages have been moved as a result of garbage collection deep inside firmware
 4. find init_0.lua snippets and continue to compare from there
 5. The "191919" adds (the file that broke SPIFFS) forces init_0.lua "data" to be moved
 6. init_0.lua by page
                             1         2         3         4         5         6         7         8         9         0         1         2         3         4         5         6         7         8         9         0         1         2         3         4         5         6
                    1234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456
    page 1: offset 776710 moved to 4157190
     776710         L...ü.function s() mytimer:unregister() end..print("2 second delay to stop code, use s()")..mytimer = tmr.create().mytimer:register(2000, tmr.ALARM_SINGLE, function().  s=nil.  mytimer:unregister().  mytimer=nil..  ----------------------------.  -- LFS bugL€..x...ð....init_0.lua.
    4157190         L...ü.function s() mytimer:unregister() end..print("2 second delay to stop code, use s()")..mytimer = tmr.create().mytimer:register(2000, tmr.ALARM_SINGLE, function().  s=nil.  mytimer:unregister().  mytimer=nil..  ----------------------------.  -- LFS bugL...ü mitigation.  -- do NOT put in LFS, 5.5x performance hit, will panic on modest file save from ide.  function ide_web_hack(payload).    local a,b,c,d,e=string.find(payload, "([A-Z]+) /([^?]*)%??(.*) HTTP").    return a,b,c,d,e.  end..  -- _init.  localL...ü n=.ode.flashindex.  n("ide_lfs_init")()..  C={v=99} -- config default.  -- dofile, supports: exact match, LFS (mod), mod.lc, mod.lua.  n("ide_dofile6")().init()..  local f="init.lua".  local d=dofile..  -- trap panic loops.  C.trap_boot_max=5.  C(...L€..x...™....init_0.lua.......................¯3°3±3#.&.ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ
                                                                                                                                                                                                                                                                                    start of next page
    page 2
     777216         L...ü mitigation.  -- do NOT put in LFS, 5.5x performance hit, will panic on modest file save from ide.  function ide_web_hack(payload).    local a,b,c,d,e=string.find(payload, "([A-Z]+) /([^?]*)%??(.*) HTTP").    return a,b,c,d,e.  end..  -- _init.  localL€..x...h....init_0.lua.......
    4157440         L...ü mitigation.  -- do NOT put in LFS, 5.5x performance hit, will panic on modest file save from ide.  function ide_web_hack(payload).    local a,b,c,d,e=string.find(payload, "([A-Z]+) /([^?]*)%??(.*) HTTP").    return a,b,c,d,e.  end..  -- _init.  localL...ü n=.ode.flashindex.  n("ide_lfs_init")()..  C={v=99} -- config default.  -- dofile, supports: exact match, LFS (mod), mod.lc, mod.lua.  n("ide_dofile6")().init()..  local f="init.lua"
                                                                                                                                                                                                                                                                                    start of next page
    page 3: corrupted page
     777984         L...ü n=node.flashindex.  n("ide_lfs_init")()..  C={v=99} -- config default.  -- dofile, supports: exact match, LFS (mod), mod.lc, mod.lua.  n("ide_dofile6")().init()..  local f="init.lua".  local d=dofile..  -- trap panic loops.  C.trap_boot_max=5.  C.tra....L.....L...L€..e.e.e.e.e.e.e.e.e.e.e.e...e.e.e.e.e.e...e.e.ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ
--> 4157696         L...ü n=.ode.flashindex.  n("ide_lfs_init")()..  C={v=99} -- config default.  -- dofile, supports: exact match, LFS (mod), mod.lc, mod.lua.  n("ide_dofile6")().init()..  local f="init.lua".  local d=dofile..  -- trap panic loops.  C.trap_boot_max=5.  C(...L€..x...™....init_0.lua.......................¯3°3±3#.&.ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ
                            x plus last 4 bytes of page are also bad                                                                                                                                                                                                            xxxxstart of next page
        *** expected the before/after lines to match
    page 4
     779008         L...üp_app_max=5.  C.trap_addr=40  -- rtcmem index (location).  C.trap_revert="".  if (dofile("ide_trap.lua",f,10).run("boot")~=nil) then.    -- stop boot, means stop executing code.    return.  end.  .  --dofile("trap_response.lua")  -- test only.  .  d("L€..x...H....init_0.lua.............................#.ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ
    4162048         L...üp_app_max=5.  C.trap_addr=40  -- rtcmem index (location).  C.trap_revert="".  if (dofile("ide_trap.lua",f,10).run("boot")~=nil) then.    -- stop boot, means stop executing code.    return.  end.  .  --dofile("trap_response.lua")  -- test only.  .  d("L...üide_lfs_flash",f,10).steps_2_and_3a() -- always needs to run from LFS, its large, else E:M error.  .  --d("init1.lua",f,10).  d("ide_init.lua",f,10).end)..mytimer:start()...ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ
                                                                                                                                                                                                                                                                                    start of next page
    page 5
     779776         L...üide_lfs_flash",f,10).steps_2_and_3a() -- always needs to run from LFS, its large, else E:M error.  .  --d("init1.lua",f,10).  d("ide_init.lua",f,10).end)..mytimer:start()...ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿL€..x...8
    4162304         L...üide_lfs_flash",f,10).steps_2_and_3a() -- always needs to run from LFS, its large, else E:M error.  .  --d("init1.lua",f,10).  d("ide_init.lua",f,10).end)..mytimer:start()...ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿL€..ø...™....init_0.lua........

---

Possible misreporting of remaining and used space

As SPIFFS free space drops, there comes a time when even a 1 byte
file can not be written, even though the reported remaining space is
in the hundreds of kilobytes.  With only a limited understanding of
SPIFFS, I present an imperfect guess.

In step 5 of the setup process, the file system state behaves as expected
but the used bytes as reported by file.fsinfo() appears low.

> =file.fsinfo()
3232629 4518    3237147
Returns: remaining (number); used (number); total (number)

---
files at the start of testing

 1. at a minimum, based on my understanding, the 4 files consume the following space
                         fsinfo()      data            idx  file  idx
    > dir()              reported      size on disk   data  name  name
    LLbin.lua             639 bytes    3 pages  768      6   256    2
    ide_c_local.lua       677 bytes    3 pages  768      6   256    2
    ide_wifi_cfg.lua      654 bytes    3 pages  768      6   256    2
    init_0.lua           1177 bytes    5 pages 1280     10   256    2
    subtotals            3147                  3584     28  1024    8
    
 2. totals from above
    3584    file data size on disk
    1024    filename data size on disk (every occurance of a filename appears alone on a page even though the SPIFFS documentation indicates that the actual filename length may be at most 31 bytes.
      28    index data
       8    index name
    4644    total
--> 4518    *** fsinfo() appears to under report space used

---

Final Notes

1. when performing this type of test on other firmware and LFS configurations
   the amount of SPIFFS space will vary
   as such, the tipping point for the error will change
2. it is quite easy to force an error with a larger file
   even when there "is" sufficient space reported
3. a 32k file was chosen to cause the error because
   it is well within the size of an LFS image
   uploading 32k via serial connection takes long enough
4. provided images and ide_wifi_cfg.lua have been
   hacked after the fact to obfuscate the SSIDs and passwords
   but should otherwise work fine.  If this is a problem,
   please comment accordingly

---

Attachments

SPIFFS files used
  20200505_test023.txt   1048576 bytes
  20200505_test006.txt   1048576 bytes
  20200505_test007.txt    327680 bytes
  20200505_test008.txt    262144 bytes
  20200505_test009.txt     32768 bytes  appears to break SPIFFS
  LLbin.lua                  639 bytes
  ide_c_local.lua            677 bytes
  ide_wifi_cfg.lua           654 bytes
  init_0.lua                1177 bytes

Results Files relevant and captured (others avialable if needed)
  esp8266_21_4M_06.bin  still some untouched pages left, all okay, no garbage collection yet
  esp8266_21_4M_07.bin  32k byte add with FTP (wifi), captures corrupted state
  esp8266_21_4M_08.bin  32k byte add with lualoader (serial), captures corrupted state 

ticket files.zip

[TerryE]

I have just tried:

function wf(n,r)
  local f,s = file.open(n..'.txt','w'), ('0123456789abcdef'):rep(64)
  for i=1,32 do f:write(s) end
  file.remove(r..'.txt')
end
function cf()
  local t = tmr.now(); wf(c, c-6); c=c+1
  print("%u %8.2f" % {c, (tmr.now() - t)/1000000})
  if c<l then node.task.post(cf) end
end
c = 0 l = 500 cf()

and this chunders away happily recycling the FS and doing GC without any obvious errors.

[TerryE]

What does

for k,v in pairs(node.getpartitiontable()) do print("%s=0x%x" % {k,v}) end

printout?

[pnkowl]

`For the SPIFFS almost "no free and never touched page" case (no corruption yet)....

for k,v in pairs(node.getpartitiontable()) do print("%s=0x%x" % {k,v}) end
stdin:1: attempt to perform arithmetic on a string value
stack traceback:
stdin:1: in main chunk
for k,v in pairs(node.getpartitiontable()) do print(k,v) end
lfs_size 262144
spiffs_addr 770048
lfs_addr 507904
spiffs_size 3424256`

[pnkowl]

Single page writes do not seem to cause the problem. I repeated the presented test case with smaller files. Corruption occurred if I approached the cliff from my stated starting point (image 06) with three 8k byte files each. I then reduced this to two 8ks, followed by one 4k, followed by two 2ks and no corruption occurred. Then followed with one 8k for good measure and all was fine. It appears the edge case is when a larger file (say 8k or more) forces the gc.

[pnkowl]

If I recall, block size is 8k (the eraseable unit).

[TerryE]

Try aligning the FS on a 1Mb boundary:

node.setpartitiontable{spiffs_addr=0x100000,spiffs_size=0x300000}

This will set the SPIFFS partition to be the last 3Mb and reboot the module. If this doesn't trigger a format then do a file.format() after restart.

PS: sorry about using the string % operator: this was introduced in a recent dev PR and has not made it into master yet.

[pnkowl]

Thanks for the try. No Go Though

Here is a more credible MVCE of the issue

1. restore firmware: python c:\esptool\esptool.py -b 115200 --port COM5 write_flash --flash_freq 80m 0x000000 esp8266_21_4M_06.bin
2. for k,v in pairs(node.getpartitiontable()) do print(k,v) end
3. node.setpartitiontable{spiffs_addr=0x100000,spiffs_size=0x300000}
4. file.format()
5. upload f0509d.lua
6. dofile("f0509d.lua")
7. f0509(10,99) -- what it does: writes a 32k file, checks it, loops to the next file,... do until done, then check them all again (if it gets that far). Start and stop file name indices need to be 2 digits, that is, in the range of (10,99). With a small firmware/LFS build 90x32k may not be enough, so, as needed execute again (appends the 90 created files with another 32k each)
   8, still fails for me on both my test ESP8266s

Find attached a serial console listing of the above process and f0509d.lua.
200509.zip

[TerryE]

Thanks. I'll give it a try

[pnkowl]

The prior case (200509.zip) comes pretty close to filling SPIFFS. Here is a more representative case of real life: several files close to the beginning of the FS, then a bunch of deleted pages and finally several larger files (representing LFS uploads). Few "free" pages are left (plus a few used pages and a whole bunch of deleted pages in the middle).

process flow

1. node.setpartitiontable{spiffs_addr=0x100000,spiffs_size=0x300000}
2. file.format()
3. restart (small changes make material differences in gc operation, do this step)
4. f0509d.lua upload (unsure if this file's presence in SPIFFS makes a difference in the outcome)
5. dofile("f0509d.lua")
6. f0509(10,91)
7. function myremove(i0,i1) for i=i0,i1 do a0="<"..i..">"; b="20200509_test"..i..".txt"; print("remove",b,file.remove(b)) end end
8. myremove(12,88)
9. f0509(89,93)
10. for k,v in pairs(filelist()) do l = string.format("%-15s",k) print(l.."   "..v.." bytes") end
11. function f(a) i=0; local src = file.open(a, "r"); if src then local line; repeat line = src:read(); if line then l=string.len(line); i=i+l; print(l,i); if(i>1953300) then print(line) end end until line == nil src:close(); src = nil end end
12. f("20200509_test90.txt")
13. for k,v in pairs(node.getpartitiontable()) do print(k,v) end
14. =file.fsinfo()

Of greatest interest in the attached listing

> f0509(89,99)
create	20200509_test89.txt
check	20200509_test89.txt	65536
create	20200509_test90.txt
check	20200509_test90.txt	12288  *** should be 64k like its neighbors ***
create	20200509_test91.txt
check	20200509_test91.txt	65536

> for k,v in pairs(file.list()) do l = string.format("%-15s",k) print(l.."   "..v.." bytes") end
20200509_test10.txt   32768 bytes
20200509_test11.txt   32768 bytes
20200509_test89.txt   65536 bytes
20200509_test90.txt   65536 bytes  *** FS thinks the file is 64k ***
20200509_test91.txt   65536 bytes
20200509_test92.txt   32768 bytes
20200509_test93.txt   32768 bytes

> function f(a) i=0; local src = file.open(a, "r"); if src then local line; repeat line = src:read(); if line then l=string.len(line); i=i+l; print(l,i); if(i>1953300) then print(line) end end until line == nil src:close(); src = nil end end
> f("20200509_test90.txt")
1024	1024
1024	2048
1024	3072
1024	4096
1024	5120
1024	6144
1024	7168
1024	8192
1024	9216
1024	10240
1024	11264
1024	12288  *** inspect again, file is way less than 64k
> 

[pnkowl]

Oops, forgot the attachement.
200509b.zip

[TerryE]

See also #3147.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.