Help with file system issue diagnosis when swapping between littlefs and fatfs.

g2gps commented 5 months ago

I've encountered an issue while swapping the file system used for our application from LittleFS to FatFS, and would appreciate any help diagnosing the problem.

For my initial investigation, I've been conducting testing with the file system utilities in NuttX, in an attempt to narrow down the scope of the issue

In each case I'm testing using the rv-virt:citest configuration, with the following changes:

diff --git a/boards/risc-v/qemu-rv/rv-virt/configs/citest/defconfig b/boards/risc-v/qemu-rv/rv-virt/configs/citest/defconfig
index 919e6ecd81..f097a6fa88 100644
--- a/boards/risc-v/qemu-rv/rv-virt/configs/citest/defconfig
+++ b/boards/risc-v/qemu-rv/rv-virt/configs/citest/defconfig
@@ -60,6 +60,11 @@ CONFIG_FAT_LFN=y
 CONFIG_FS_AIO=y
 CONFIG_FS_FAT=y
 CONFIG_FS_HOSTFS=y
+CONFIG_FS_LITTLEFS=y
+CONFIG_FS_LITTLEFS_BLOCK_CYCLE=-1
+CONFIG_FS_LITTLEFS_BLOCK_SIZE_FACTOR=4
+CONFIG_FS_LITTLEFS_CACHE_SIZE_FACTOR=4
+CONFIG_FS_LITTLEFS_PROGRAM_SIZE_FACTOR=1
 CONFIG_FS_NAMED_SEMAPHORES=y
 CONFIG_FS_PROCFS=y
 CONFIG_FS_ROMFS=y
@@ -132,7 +137,9 @@ CONFIG_TESTING_LTP=y
 CONFIG_TESTING_MM=y
 CONFIG_TESTING_OPEN_MEMSTREAM=y
 CONFIG_TESTING_OSTEST=y
+CONFIG_TESTING_SMART_TEST=y
 CONFIG_TESTING_SCANFTEST=y
 CONFIG_TESTS_TESTSUITES=y
+CONFIG_TESTS_TESTSUITES_MOUNT_DIR="/mnt"
 CONFIG_TLS_NELEM=8
 CONFIG_USEC_PER_TICK=1000

and a rc.sysinit with:

mkrd -m 1 -s 512 2048
mkrd -m 2 -s 512 2048
mkfatfs /dev/ram1
mkdir /mnt
mount -t vfat /dev/ram1 /mnt/fatfs
mount -t littlefs -o forceformat /dev/ram2 /mnt/littlefs

I move the mount points to /mnt for the cmocka and fstests

Here's the testing I've done so far

smart test

smart_test fails on both fatfs and littlefs with multiple errors, for example:

nsh> smart_test -s 1000 -l 1000 /mnt/fatfs
Seek error on line 775
         Expected "This is line 775 at offset 64
"
         Received ""
996
Seek error on line 140
         Expected "This is line 140 at offset 64
"
         Received ""
997
Seek error on line 762
         Expected "This is line 762 at offset 64
"
         Received ""
998
Seek error on line 55
         Expected "This is line 55 at offset 64
"
         Received ""

cmocka

cmocka --suite fshas failures on fatfs:

[ RUN      ] test_nuttx_fs_stat01
[  ERROR   ] --- 1 != 0
[   LINE   ] --- kernel/fs/cases/fs_stat_test.c:160: error: Failure!
.....
.....
[ RUN      ] test_nuttx_fs_fstat01
[  ERROR   ] --- 0 != 1
[   LINE   ] --- kernel/fs/cases/fs_fstat_test.c:96: error: Failure!
[  FAILED  ] test_nuttx_fs_fstat01

and littlefs:

[ RUN      ] test_nuttx_fs_stat01
[  ERROR   ] --- 4 != 0
[   LINE   ] --- kernel/fs/cases/fs_stat_test.c:160: error: Failure!

fstest

Passes on littlefs:

nsh> fstest -m /mnt -n 10
....
Final memory usage:
VARIABLE  BEFORE   AFTER    DELTA
======== ======== ======== ========
arena     1e9eadc  1e9eadc        0
ordblks         4        4        0
mxordblk  1c92490  1c92490        0
uordblks   20a514   20a514        0
fordblks  1c945c8  1c945c8        0
File system tests done... OK: 20, FAILED: 0

Passes on fatfs:

nsh> fstest -m /mnt -n 10
Final memory usage:
VARIABLE  BEFORE   AFTER    DELTA
======== ======== ======== ========
arena     1e9eadc  1e9eadc        0
ordblks         4        4        0
mxordblk  1c94498  1c94498        0
uordblks   209614   209614        0
fordblks  1c954c8  1c954c8        0
File system tests done... OK: 20, FAILED: 0

Some initial thoughts:

The portion of our application which is problematic makes heavy use of ftell and fseek, however the data inconsistency is only apparent when using fatfs. We've been using littleFS for around 9 months without issue.
fstest doesn't make use of file streams, or seek, so it may not be catching the test which fails.
The cmocka failures seem unreleated, but are worth noting.
The smart_test file system check hints that something may be wrong, although I haven't looked any further yet.

Possibly there is further testing which could be done to further narrow down the issue? Or somebody else has noticed a similar issue?

acassis commented 5 months ago

@g2gps I think some FS doesn't support all the features required by smart_test testing too. Not sure if this is the issue with FATFS, Also you can enable File System debug to collect more information and find the root causes

g2gps commented 4 months ago

I set up an example program to look at seek's behaviour:


#ifdef __NuttX__
#include <nuttx/config.h>
#else
#define FAR
#endif

#include <errno.h>
#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/stat.h>
#include <unistd.h>

char* vbuffer;

FILE *test_open(const char *name, const char *mode, size_t bufsiz)
{
  FILE *fp = NULL;

  fp = fopen(name, mode);
  if(!fp)
  {
    return fp;
  }
  printf("open %s with mode %s\n", name, mode);

  if (bufsiz)
    {
      vbuffer = malloc(bufsiz);
      if (!vbuffer)
        {
          return NULL;
        }
      setbuffer(fp, vbuffer, bufsiz);
      printf("set stdio buffer to: %p size: %zu\n", vbuffer, bufsiz);
    }

  return fp;
}

int test_close(FILE *fp)
{
  if(vbuffer)
    {
      free(vbuffer);
    }
  return fclose(fp);
}

ssize_t test_read(FILE *fp, char* buffer, size_t buflen)
{
  ssize_t ret = fread(buffer, 1, buflen, fp);
  printf("read: '%s' len: %zd\n", buffer, ret);
  return ret;
}

ssize_t test_write(FILE *fp, const char* text)
{
  ssize_t ret = fwrite(text, 1, strlen(text) + 1, fp);
  printf("write: %s, len: %zd\n", text, ret);
  return ret;
}

ssize_t test_ftell(FILE *fp)
{
  ssize_t pos =  ftell(fp);
  printf("file position %zu\n", pos);
  return pos;
}

ssize_t test_seek(FILE *fp, size_t pos)
{
  int ret = fseek(fp, pos, SEEK_SET);
  printf("seek to: %zu, ret: %d\n", pos, ret);
  return test_ftell(fp);
}

ssize_t test_file_size(FILE *fp)
{
  ssize_t current = ftell(fp);
  fseek(fp, 0, SEEK_END);
  ssize_t end = ftell(fp);
  fseek(fp, current, SEEK_SET);
  printf("file size %zd\n", end);
  return end;
}

int main(int argc, FAR char *argv[])
{
  const char *filename = "test_file";
  char read_buffer[80] = { 0 };
  size_t stdio_buffer_size = 0;
  FILE *fp;

  fp = test_open(filename, "w", stdio_buffer_size);
  test_ftell(fp);
  test_write(fp, filename);
  test_ftell(fp);
  test_file_size(fp);
  test_close(fp);

  fp = test_open(filename, "r", stdio_buffer_size);
  test_ftell(fp);
  test_read(fp, read_buffer, sizeof(read_buffer));
  test_ftell(fp);
  test_file_size(fp);

  // Seek past the end of the file.
  test_seek(fp, strlen(filename) * 2);
  test_ftell(fp);

  memset(read_buffer, 0, sizeof(read_buffer));
  test_read(fp, read_buffer, sizeof(read_buffer));
  test_ftell(fp);
  test_file_size(fp);

  test_close(fp);
  return 0;
}

When this is run on a littlefs based file system, or when I compile or run this on my Linux host:

open test_file with mode w
file position 0
write: test_file, len: 10
file position 10
file size 10
open test_file with mode r
file position 0
read: 'test_file' len: 10
file position 10
file size 10
seek to: 18, ret: 0
file position 18
file position 18
read: '' len: 0
file position 18
file size 10

However, when run on a fatfs based file system:

open test_file with mode w
file position 0
write: test_file, len: 10
file position 10
file size 10
open test_file with mode r
file position 0
read: 'test_file' len: 10
file position 10
file size 10
seek to: 18, ret: 0
file position 18
file position 18
read: '��' len: 80
file position 98
file size 10

The second read, when seek is set past the eof seems incorrect for FAT. I'm expecting it to return 0 bytes read, not modify the buffer, and not move the file position.

I'm not sure yet if this is the exact cause of the issue, but as far as I understand this behaviour isn't quite right.

The number of bytes read is 80, which is the size of the buffer I provided, so perhaps there is an issue with the return value of the buffer passed down to fatfs when it is larger the the stdio buffer, whose default is 64.

Thanks for the suggestion @acassis, I added file system logging, but it doesn't give any hints.

rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512
rd_read: sector: 7 nsectors: 1 sectorsize: 512
rd_read: Transfer 512 bytes from 0x8004bfa8
open test_file with mode w
file position 0
write: test_file, len: 10
file position 10
rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512
rd_write: sector: 7 nsectors: 1 sectorsize: 512
rd_write: Transfer 512 bytes to 0x8004bfa8
rd_read: sector: 1 nsectors: 1 sectorsize: 512
rd_read: Transfer 512 bytes from 0x8004b3a8
fat_currentsector: position=0 currentsector=39 sectorsincluster=2
file size 10
rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512
rd_write: sector: 39 nsectors: 1 sectorsize: 512
rd_write: Transfer 512 bytes to 0x8004ffa8
rd_write: sector: 1 nsectors: 1 sectorsize: 512
rd_write: Transfer 512 bytes to 0x8004b3a8
rd_write: sector: 4 nsectors: 1 sectorsize: 512
rd_write: Transfer 512 bytes to 0x8004b9a8
rd_read: sector: 7 nsectors: 1 sectorsize: 512
rd_read: Transfer 512 bytes from 0x8004bfa8
rd_write: sector: 7 nsectors: 1 sectorsize: 512
rd_write: Transfer 512 bytes to 0x8004bfa8
rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512
open test_file with mode r
file position 0
rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512
fat_currentsector: position=0 currentsector=39 sectorsincluster=2
rd_read: sector: 39 nsectors: 1 sectorsize: 512
rd_read: Transfer 512 bytes from 0x8004ffa8
rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512
read: 'test_file' len: 10
file position 10
file size 10
seek to: 18, ret: 0
file position 18
file position 18
rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512
read: '' len: 80
file position 98
file size 10
rd_geometry: Entry
rd_geometry: available: true mediachanged: false writeenabled: true
rd_geometry: nsectors: 2048 sectorsize: 512

g2gps commented 4 months ago

Adding a larger stream buffer changes the behaviour for fatfs. Setting stdio_buffer_size = 4096:

open test_file with mode w
set stdio buffer to: 0x80248290 size: 4096
file position 0
write: test_file, len: 10
file position 10
file size 10
open test_file with mode r
set stdio buffer to: 0x80248290 size: 4096
file position 0
read: 'test_file' len: 10
file position 10
file size 10
seek to: 18, ret: 0
file position 18
file position 18
read: '' len: 0
file position 1024
file size 10

acassis commented 4 months ago

@xiaoxiang781216 @g2gps why to reopen it?

g2gps commented 4 months ago

I still have an issue when switching between littlefs and fatfs. However, I'm currently unable to come up with a reproducible test case.

apache / nuttx