PR #6456 Edited VFSFileImpl crashes

[Jason2866]

Since this commit we have crashes using the Filesystem. Reverted the PR, Filesystem and SD Card useage is working again. Tbh, not really fully understanding what the PR does.
See comment #6456 (comment) too
@P-R-O-C-H-Y @me-no-dev

[P-R-O-C-H-Y]

Hi @Jason2866,
With implementation of checking sd_status the reading speeds got a lot slower. Thats because the sd_status check is called every read(). So an example if you want to read 512 bytes of data FILE.read(buf,512); without PR #6456 the fread() will internally call read() for every 128 bytes of data. So the sd_status is called 4 times for chunk of 512 bytes. If we call directly once read() the sd_status is called only once. So for bigger chunks of data its a huge speed improvement. See table below.
With that to improve the speed the most, I implemented the read() to be called when chunks are bigger than 128 bytes (file internal buffer size).

1 MB file ->	fread time[ms]	read time[ms]
64 bytes chunks	1502	1826
128 bytes chunks	1422	1354
256 bytes chunks	1382	1118
512 bytes chunks	1366	934
1024 bytes chunks	1351	805
2048 bytes chunks	1347	705
4096 bytes chunks	1345	649
8192 bytes chunks	1345	621

I tested reading different chunks of data to test switching between fread() and read() and I got every time the right data.

But its good that we released the 2.0.3-RC1 and all of you are testing that. I can say that the SDWebServer is not working with switching between read/fread or only when using read(). Its works only with fread() (the previous implementation). I'm testing and sorting out why its not working at all.

I will appriciate any advices or test cases/sketches to be able to test more scenarios.

[Jason2866]

Thx for your fast answer! Have you seen the comment / questions from @s-hadinger in the PR?
Regarding a test sketch, it is difficult since the Filesystem and SD Card access is a part of the Project Tasmota and can not be used standalone or extracted. If you have a changed version, we will test asap.

[P-R-O-C-H-Y]

Answer for @s-hadinger comment in PR. To be able to discuss everything in one place :)

Scenario 1:
open file
read 128 bytes
read 128 bytes
close

# bytes('504B03040A0000000000B8B8755431C19D1968000000680000000B001C006175...')
# bytes('6C6174696E312873697A6529600A0A696D706F727420726F626F746F636F6E64...')

Scenario 2:
open file
read 128 bytes
read 256 bytes
close

# bytes('504B03040A0000000000B8B8755431C19D1968000000680000000B001C006175...')
# bytes('1300207C9004822410900F1004C170003804E626822258748689F0180000200C...')

In scenario 2, the second read of 256 bytes following the first read of 128 bytes provides wrong content
Edit: the second read for 256 bytes actually starts at offset 0x1000 in the file, instead of offset 0x80. I do see a crash later as a hint of corrupt memory.

I have tested this in Arduino and I don't get wrong results as you did, everything is good.

Scenario 1 - read 128 + read 128

bytes('89504E47DA1AA000D49484452003580015A86...')
bytes('9DB367EF3B37EF97FFB9EFE6FF7D2FDF39170C...')

Scenario 2 - read 128 + read 256

bytes('89504E47DA1AA000D49484452003580015A86...')
bytes('9DB367EF3B37EF97FFB9EFE6FF7D2FDF39170C...')

I have some questions:

• __fpending(_f); is normally for the output buffer, not the input buffer. Am I missing something?
• lseek(fileno(_f),(-128+bytesinbuf),SEEK_CUR); why is the file seeked 128 bytes ahead of bytesinbuf? Are we even sure that >bytesinbuf is always greater than 128? If not the substraction is invalid and yields to an overflow.

1. __fpending(_f); - It actually checks how many bytes are in buffer no matter if reading or writing. I need to check the buffer when switching from fread to read. Because fread always read in 128 bytes chunks so if you want to read 200 bytes, it will read 256 and store the 56 left in the buffer so if you call fread again, it will be fastly reader from internal buffer.
   But that's the point where can be a problem when switching to read when bytes are stuck in buffer.
   the read.

I will give a great example - Thanks to @igrr

Now imagine you call fread to read 16 bytes, then call read to read 512 bytes.

1. fread sees that the buffer is empty, calls read and gets 128 bytes, puts them into the FILE* internal buffer
2. fread takes 16 bytes from the internal buffer and returns them to the caller. Then it adjusts the read pointer of the internal buffer.
3. Next, read is called to read 512 bytes. It reads directly from the file, since it doesn't know anything about FILE* internal buffer (it is a lower level function). These 512 bytes are returned to the caller.

So as a result, the first call reads bytes 0-15 from the file, and the next call reads bytes 128-667 from the file, instead of 16-571. Bytes 16-255 are still stuck in FILE* internal buffer.

You can only call read if you have made sure there are no bytes left in the internal buffer of FILE*.
--> Thats why I am clearing the internal buffer by fpurge() and setting the pointer back for number bytes with lseek(fileno(_f),(-128+bytesinbuf),SEEK_CUR); that have been already read and stored in internal buffer by fread() and cleared before read() so they can be read again by read()

I have tested different scenarios where its switches between fread and read and checked what's happening inside buffer and adjusting the pointer. Everything worked fine and I get the right data.

The table below show how bytesinbuf and pointer behave. The read 512 is the only one called that call read directly (size > 128)

Func/Variable	bytesinbuf	Pointer
read 16	16	16
read 512	16	16
read 104	120	120
read 8	128	128
read 128	128	256
read 1	1	257

2. • lseek(fileno(_f),(-128+bytesinbuf),SEEK_CUR); I can edit that to always check the size of the buffer first. But for me I always had 128 bytes buffer.

[P-R-O-C-H-Y]

What I don't get why In scenario 2 from @s-hadinger, the second read for 256 bytes actually starts at offset 0x1000 in the file, instead of offset 0x80. I do see a crash later as a hint of corrupt memory. Thats 4kb wrong offset. In the code it should only move from 0 to 128 bytes back, not ahead.

[s-hadinger]

I have not rational explanation why I get data from offset 0x1000. Maybe it's just a side effect of some memory corruption.

Thanks for your detailed response.

[P-R-O-C-H-Y]

I have found that using LittleFS the buffer size is 4096 bytes. Thats doing the x1000 offset. Working on fix now ;)

[Jason2866]

Thank you for the detailed explanation. But "somewhere" is "something" wrong which generates issues.
We are not the only ones which have problems with this change. Issue #6502 identified this change as reason for the problems too.
Maybe it is a side effect with LittleFS. It is involved in both cases.

[P-R-O-C-H-Y]

Yes there is definitely something wrong, I am working on that :)
For what I tested even SDWebServer is not working with the read() implementation as it is now.
I saw you PR - hot fix and seems to be reasonable now till it gets fixed.

[P-R-O-C-H-Y]

@Jason2866 @s-hadinger
Can you test this changed implementation of read? No PR yet, want to make sure it works :)
Thank you for testing!

size_t VFSFileImpl::read(uint8_t* buf, size_t size)
{
    if(_isDirectory || !_f || !buf || !size) {
        return 0;
    }
  
    if(size > READ_SIZE_SWITCH)
    {
        //check some data in buffer exists –> clear buffer and move pointer to deleted data
        size_t buf_size = __fbufsize(_f);
        size_t bytesinbuf = __fpending(_f);
        if (bytesinbuf && (bytesinbuf != buf_size))  //buffer lenght is 128 bytes
        {
            fpos_t pointer = 0;
            fpurge(_f);
            fgetpos(_f, &pointer);
            lseek(fileno(_f),(-pointer+bytesinbuf),SEEK_CUR);
        }

        int res = ::read(fileno(_f), buf, size);
        if (res < 0) {
            // an error occurred
            log_d("ERROR OCCURED");
            return 0;
        }
        return res;
    }
    else
    {
        return fread(buf, 1, size, _f);
    }
}

[P-R-O-C-H-Y]

Great! I am gonna clean and comment the code a bit and post a PR :) but i think it still wont work for SDwebserver.. There is some different problem. Will continue on that tomorrow ;)

[s-hadinger]

I added logs. Here is the sequence:

• open file
• seek to position 8094
• read 256 bytes

The bytes returned are actually from offset 4008 instead of 8094 (decimal offsets)

Reading the entire file at once does work ok.

[P-R-O-C-H-Y]

I added logs. Here is the sequence:

• open file
• seek to position 8094
• read 256 bytes

The bytes returned are actually from offset 4008 instead of 8094 (decimal offsets)

Reading the entire file at once does work ok.

Will test this scenario tomorrow :)
Thanks for testing.

[s-hadinger]

I'm sorry but there is still something wrong with this latest version. It's yet another problem but my zip file parser still fails. It's too late for me do go deeper into it.

Edit: I'm testing with M5Stack_Fire.autoconf in the file system.

Works:

f=open("M5Stack_Fire.autoconf")
f.seek(8094)
s=f.read(127)
f.close()
print(s)

# shows valid Berry code from `autoexec.be

Does not work:

f=open("M5Stack_Fire.autoconf")
f.seek(8094)
s=f.read(129)
f.close()
print(s)

# `s` is empty, meaning that the read failed

[P-R-O-C-H-Y]

I'm sorry but there is still something wrong with this latest version. It's yet another problem but my zip file parser still fails. It's too late for me do go deeper into it.

Edit: I'm testing with M5Stack_Fire.autoconf in the file system.

Works:

f=open("M5Stack_Fire.autoconf")
f.seek(8094)
s=f.read(127)
f.close()
print(s)

# shows valid Berry code from `autoexec.be

Does not work:

f=open("M5Stack_Fire.autoconf")
f.seek(8094)
s=f.read(129)
f.close()
print(s)

# `s` is empty, meaning that the read failed

I see the problem, the f.seek() function calls internal fseek(). You can see that in changed read code there is used lseek(), that because fseek was not working for read() (only works for fread). I will post PR with all changes and add this too. So you can always that the updated PR :)

[P-R-O-C-H-Y]

Created new PR #6536 - with all changes. Please if you can test this. Edited file.seek to be working.
Please let me know if there is still some problem :)

[P-R-O-C-H-Y]

Actually I suspect tell() to be wrong now:

f=open("M5Stack_Fire.autoconf")
f.seek(8480)
d=f.read(32)
d=f.read(256)
print(f.tell())
f.close()

# output: 8795
# correct output should be: 8480+32+256 = 8768

Changed position function to call seek with no offset instead of ftell. Can you try if now the position returned works?

[P-R-O-C-H-Y]

Hmmm. It looks to be working but it's super-super slow for a reason I can't explain. There is definitely some nasty side-effect.

When loading LVGL fonts, the reads are done 1 byte per one byte. I.e. a call to f->read() for each byte.

I suspect a problem in some other APIs.

This is something to take a deeper look at. Thanks for info and testing

[s-hadinger]

Not good:

f=open("M5Stack_Fire.autoconf")
f.seek(8480)
d=f.read(32)
d=f.read(256)
print(f.tell())
f.close()
# prints 8480 -- like if the reads did not happen

Same result for other starting points:

f=open("M5Stack_Fire.autoconf")
f.seek(7000)
d=f.read(32)
d=f.read(256)
print(f.tell())
f.close()
# prints 8480 as well

[s-hadinger]

Its even worse:

f=open("M5Stack_Fire.autoconf")
f.seek(32)
d=f.read(32)
print(f.tell())
d=f.read(224)
print(f.tell())
f.close()
# prints:
#  4128  -- should be 64
#  4352  -- should be 288

I.e. a seek followed by a short read already pushes ahead by 0x1000.

[P-R-O-C-H-Y]

Sorry that I did not replied for few days. I'm now working on 2 solutions so there won't be mix of fread/read but only 1 of it. Actually it seems we will stick with same fread implementation as it was before. There will be small change in file buffering causing SD lib to be slow.

[P-R-O-C-H-Y]

New PR created #6569.

[s-hadinger]

I confirm all is working well now.

However because of declaring virtual bool setBufferSize(size_t size) = 0;, it forces me to add this method to my existing code (which I don't need). Not a big deal but it may cause a some other compilation issues.

Why not set a do-nothing implementation by default?

[s-hadinger]

Anyways I did the change in Tasmota to make compilation work with this PR.