V2 alpha: lfs_cache_prog: assert(pcache->block == 0xffffffff)

[TheLoneWolfling]

The following test case:

#include <assert.h>
#include <stdlib.h>
#include "lfs.h"
#include "emubd/lfs_emubd.h"

#define REQUIRE(x) do {if(!(x)) {assert(false); exit(1);}} while(0);

lfs_t lfs;
lfs_emubd_t bd;

int wrap_lfs_emubd_prog(const struct lfs_config *c, lfs_block_t block,
        lfs_off_t off, const void *buffer, lfs_size_t size) {
    static size_t count = 0;
    int r = lfs_emubd_prog(c, block, off, buffer, size);
    if (count++ == 52) {
        r = -2718; // Semi-arbitrary negative error code.
    }
    printf("->prog(%p, %u, %u, %p, %u) = %d;\n", (void *) c, block, off, buffer, size, r);
    return r;
}

const lfs_config cfg = {
    .context          = &bd,
    .read             = &lfs_emubd_read,
    .prog             = &wrap_lfs_emubd_prog,
    .erase            = &lfs_emubd_erase,
    .sync             = &lfs_emubd_sync,

    .read_size        = 2,
    .prog_size        = 1,
    .block_size       = 128,
    .block_count      = 64,
    .block_cycles     = 1024*1024,
    .cache_size       = 2,
    .lookahead_size   = 128,
    .read_buffer      = NULL,
    .prog_buffer      = NULL,
    .lookahead_buffer = NULL,
    .name_max         = 48,
    .file_max         = 1024*1024,
    .attr_max         = 48,
};

int main(void) {
    lfs_file_t fileA, fileB, fileC;
    lfs_emubd_create(&cfg, "blocks");

    REQUIRE(lfs_format(&lfs, &cfg) == 0);
    REQUIRE(lfs_mount(&lfs, &cfg) == 0);
    
    REQUIRE(lfs_file_open(&lfs, &fileA, "A", LFS_O_RDONLY | LFS_O_CREAT) == 0);
    REQUIRE(lfs_file_close(&lfs, &fileA) == 0);
    
    REQUIRE(lfs_file_open(&lfs, &fileB, "B", LFS_O_RDONLY | LFS_O_CREAT) == 0);
    REQUIRE(lfs_file_close(&lfs, &fileB) == 0);
    
    REQUIRE(lfs_file_open(&lfs, &fileC, "B", LFS_O_RDONLY | LFS_O_TRUNC) == 0);
    REQUIRE(lfs_file_sync(&lfs, &fileC) == -2718);
    
    lfs_file_close(&lfs, &fileC); // Asserts within here.
    
    lfs_emubd_destroy(&cfg);
}

Dies with lfs.c:223: lfs_bd_prog: Assertion 'pcache->block == 0xffffffff' failed.

It looks as though the lfs_file_sync isn't properly clearing out pcache if the program fails with a non-LFS_ERR_CORRUPT error code.

Stack trace:

raise (raise.c:51)
abort (abort.c:89)
__assert_fail_base (assert.c:92)
__assert_fail (assert.c:101)
lfs_bd_prog (lfs.c:194)
lfs_dir_commitprog (lfs.c:1181)
lfs_dir_commitattr (lfs.c:1204)
lfs_dir_traverse (lfs.c:751)
lfs_dir_commit (lfs.c:1723)
lfs_file_sync (lfs.c:2601)
lfs_file_close (lfs.c:2404)
main (main_test.cpp:60)

Other info:

• Commit is 10dfc36 Fixed issue with long names causing unbounded recursion (v2-alpha)
• Makefile compiled with default arguments (x86_64).

[TheLoneWolfling]

Backtrace with locals (from GDB):

#4  in lfs_bd_prog (lfs=0x555555761120 <lfs>, pcache=0x555555761138 <lfs+24>, rcache=0x555555761120 <lfs>, validate=false, block=0, 
    off=94, buffer=0x7fffffffde04, size=4) at lfs.c:223
        data = 0x7fffffffde04 "\360\017\364\004\001"
        __PRETTY_FUNCTION__ = "lfs_bd_prog"
#5  in lfs_dir_commitprog (lfs=0x555555761120 <lfs>, commit=0x7fffffffdf90, buffer=0x7fffffffde04, size=4) at lfs.c:1181
        err = -267389948
#6  in lfs_dir_commitattr (lfs=0x555555761120 <lfs>, commit=0x7fffffffdf90, tag=537921536, buffer=0x555555774210) at lfs.c:1204
        dsize = 4
        ntag = 83103728
        err = 0
#7  in lfs_dir_commit_commit (p=0x7fffffffdfd0, tag=537921536, buffer=0x555555774210) at lfs.c:1406
        commit = 0x7fffffffdfd0
#8  in lfs_dir_traverse (lfs=0x555555761120 <lfs>, dir=0x7fffffffe0ec, off=94, ptag=3491757060, attrs=0x7fffffffe070, attrcount=1, 
    hasseenmove=false, tmask=0, ttag=0, begin=0, end=0, diff=0, cb=0x5555555584be <lfs_dir_commit_commit>, data=0x7fffffffdfd0) at lfs.c:751
        err = 0
        tag = 537921536
        buffer = 0x555555774210
        disk = {block = 4294958848, off = 32767}
        mask = 2146435072
#9  in lfs_dir_commit (lfs=0x555555761120 <lfs>, dir=0x7fffffffe0ec, attrs=0x7fffffffe060, attrcount=2) at lfs.c:1723
        commit = {block = 0, off = 94, ptag = 3491757060, crc = 4294967295, begin = 94, end = 120}
        err = 32767
        deletetag = 4294967295
        createtag = 4294967295
        __PRETTY_FUNCTION__ = "lfs_dir_commit"
        copy = {pair = {2, 0}, rev = 1431653632, off = 21845, etag = 0, count = 98, erased = false, split = false, tail = {537921536, 4288921339}}
#10 in lfs_file_sync (lfs=0x555555761120 <lfs>, file=0x7fffffffe0e0) at lfs.c:2601
        type = 513
        buffer = 0x555555774210
        size = 0
        ctz = {head = 0, size = 0}
        err = 0
#11 in lfs_file_close (lfs=0x555555761120 <lfs>, file=0x7fffffffe0e0) at lfs.c:2404
        err = 21845
#12 in main () at main_test.cpp:60
        fileA = {next = 0x0, id = 1, type = 1 '\001', m = {pair = {0, 1}, rev = 15, off = 73, etag = 3491757060, count = 2, erased = true, split = false, 
            tail = {4294967295, 4294967295}}, ctz = {head = 4294967294, size = 0}, flags = 1048833, pos = 0, block = 21845, off = 142, cache = {
            block = 4294967294, off = 0, size = 2, buffer = 0x555555774210 "\377$\255\373\377\177"}, cfg = 0x55555555f180 <defaults>}
        fileB = {next = 0x0, id = 2, type = 1 '\001', m = {pair = {0, 1}, rev = 15, off = 94, etag = 3491757060, count = 3, erased = true, split = false, 
            tail = {4294967295, 4294967295}}, ctz = {head = 4294967294, size = 0}, flags = 1048833, pos = 0, block = 0, off = 4146172768, cache = {
            block = 4294967294, off = 0, size = 2, buffer = 0x555555774210 "\377$\255\373\377\177"}, cfg = 0x55555555f180 <defaults>}
        fileC = {next = 0x0, id = 2, type = 1 '\001', m = {pair = {0, 1}, rev = 15, off = 94, etag = 3491757060, count = 3, erased = true, split = false, 
            tail = {4294967295, 4294967295}}, ctz = {head = 4294967294, size = 0}, flags = 1115137, pos = 0, block = 32767, off = 4149439232, cache = {
            block = 4294967294, off = 0, size = 2, buffer = 0x555555774210 "\377$\255\373\377\177"}, cfg = 0x55555555f180 <defaults>}
        __PRETTY_FUNCTION__ = "int main()"

[geky]

Thanks for raising an issue and the great example, sorry about the long delay. I've pushed up a fix on the v2-alpha branch: #85

The issue was with lfs_file_sync not setting the LFS_F_ERRED flag on error. This prevents lfs_file_close from creating further problems, which is needed for cleaning up the file resources. Otherwise lfs_file_close tries to write to the already dirty file cache as a part of writing out the file.

Properly handling all block device errors is one area that needs work and would benefit greatly from actual coverage information.

[drmpf]

Adafruit nRF52 board support V1.3.0 still has this problem.
file system is un-stable. board locks up after this error.

Seems to triggered by truncate(0) This method fails

bool saveLastCmd(SafeString &sfCmd) {
  if (debugPtr) {
    debugPtr->print("calling saveLastCmd (");
    debugPtr->print(sfCmd); debugPtr->println(")");
  }
  if (!initialzeFileSystem()) {
    return fileSystemInitializedResult;
  }
  sfCmd.trim();
  if (sfCmd.endsWith(',')) {
    sfCmd.removeLast(1); // remove last char
  }
  File file(InternalFS);

  if (!(file.open(FILENAME, FILE_O_WRITE))) {
    if (debugPtr) {
      debugPtr->print("Error: File: '");
      debugPtr->print(FILENAME);
      debugPtr->println("' failed to open");
    }
    return false;
  }
  // else
  if (!file.truncate(0)) { // truncate() truncates at current file pointer position!!
    if (debugPtr) {
      debugPtr->print("Error: Positioning to 0 for file '");
      debugPtr->print(FILENAME);
      debugPtr->println("'");
    }
    file.close();
    return false;
  }
  if (debugPtr) {
    debugPtr->print(" write "); debugPtr->print(sfCmd); debugPtr->println();
  }
  size_t count = file.write(sfCmd.c_str(), sfCmd.length());
  file.close();
  if (count != sfCmd.length()) {
    if (debugPtr) {
      debugPtr->print("Error: Writing cmd '");
      debugPtr->print(sfCmd);
      debugPtr->println(" to file '");
      debugPtr->print(FILENAME);
      debugPtr->println("'");
    }
    if (!InternalFS.remove(FILENAME)) {
      if (debugPtr) {
        debugPtr->print("Error: Delete of file '");
        debugPtr->print(FILENAME);
        debugPtr->println("' failed");
      }
    }
    return false;
  }
  return true;
}

This method seems to work (so far)

bool saveLastCmd(SafeString &sfCmd) {
  if (debugPtr) {
    debugPtr->print("calling saveLastCmd (");
    debugPtr->print(sfCmd); debugPtr->println(")");
  }
  if (!initialzeFileSystem()) {
    return fileSystemInitializedResult;
  }
  sfCmd.trim();
  if (sfCmd.endsWith(',')) {
    sfCmd.removeLast(1); // remove last char
  }
  InternalFS.remove(FILENAME);
  File file(InternalFS);

  if (!(file.open(FILENAME, FILE_O_WRITE))) {
    if (debugPtr) {
      debugPtr->print("Error: File: '");
      debugPtr->print(FILENAME);
      debugPtr->println("' failed to open");
    }
    return false;
  }
  if (debugPtr) {
    debugPtr->print(" write "); debugPtr->print(sfCmd); debugPtr->println();
  }
  size_t count = file.write(sfCmd.c_str(), sfCmd.length());
  file.close();
  if (count != sfCmd.length()) {
    if (debugPtr) {
      debugPtr->print("Error: Writing cmd '");
      debugPtr->print(sfCmd);
      debugPtr->println(" to file '");
      debugPtr->print(FILENAME);
      debugPtr->println("'");
    }
    if (!InternalFS.remove(FILENAME)) {
      if (debugPtr) {
        debugPtr->print("Error: Delete of file '");
        debugPtr->print(FILENAME);
        debugPtr->println("' failed");
      }
    }
    return false;
  }
  return true;
}