SPIFFS println weird behavior with long strings

[fabianoriccardi]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: Wemos D1 mini
• Core Version: commit: bf2882d
• Development Env: Arduino IDE
• Operating System: Windows

Settings in IDE

• Module: Wemos D1 mini
• Flash Mode: dio
• Flash Size: 4MB
• lwip Variant: v2 Lower Memory
• Reset Method: default
• Flash Frequency: 40Mhz
• CPU Frequency: 80Mhz
• Upload Using: SERIAL
• Upload Speed: 916200

Problem Description

Sporadically, File::println("message") fails, and instead of recording "\r\n" it prints 0xFFFF. In this sketch, this happens only with long messages (i.e. >350 chars). However, in more complicated sketches (where multiple write per lines occurs), it happens even with short strings. It happens with Arduino Core 3.x.x, as well as the latest commit, but it works fine in previous releases (2.7.4 and lower).

I know that SPIFFS is deprecated, but this seems a regression and it should be mentioned.

Sketch

# print 10 lines on file and then print back to Serial.

#include <FS.h>

void setup() {
  Serial.begin(115200);
  while(!Serial);
  Serial.println();
  
  // You mays need to format the flash before using it
  //SPIFFS.format();

  if(SPIFFS.begin()){
    Serial.println("Filesystem mounted successfully");
  }else{
    Serial.println("Filesystem NOT mounted. System halted");
    while(1) delay(100);
  }
}

void loop() {
  for(int i=0; i<10; ++i){
    Serial.println(i);
    File f = SPIFFS.open("/mytext.txt", "a");
    if(f){
      f.println("{\"glossary\":{\"title\":\"example glossary\",\"GlossDiv\":{\"title\":\"S\",\"GlossList\":{\"GlossEntry\":{\"ID\":\"SGML\",\"SortAs\":\"SGML\",\"GlossTerm\":\"Standard Generalized Markup Language\",\"Acronym\":\"SGML\",\"Abbrev\":\"ISO 8879:1986\",\"GlossDef\":{\"para\":\"A meta-markup language, used to create markup languages such as DocBook.\",\"GlossSeeAlso\":[\"GML\",\"XML\"]},\"GlossSee\":\"markup\"}}}}}");      
      f.close();  
    } else {
      Serial.println("error");
    }
    delay(1000);
  }

  File f = SPIFFS.open("/mytext.txt", "r");
  while(f.available()){
    Serial.println(f.readStringUntil('\n'));
  }
  f.close();
  SPIFFS.remove("/mytext.txt");
}

Debug Messages

Sometimes 2 messages are printed on the same line. It seems that println prints 0xFFFF instead of "\r\n". An example (there are 2 '⸮' in the middle of the string):

{"glossary":{"title":"example glossary","GlossDiv":{"title":"S","GlossList":{"GlossEntry":{"ID":"SGML","SortAs":"SGML","GlossTerm":"Standard Generalized Markup Language","Acronym":"SGML","Abbrev":"ISO 8879:1986","GlossDef":{"para":"A meta-markup language, used to create markup languages such as DocBook.","GlossSeeAlso":["GML","XML"]},"GlossSee":"markup"}}}}}⸮⸮{"glossary":{"title":"example glossary","GlossDiv":{"title":"S","GlossList":{"GlossEntry":{"ID":"SGML","SortAs":"SGML","GlossTerm":"Standard Generalized Markup Language","Acronym":"SGML","Abbrev":"ISO 8879:1986","GlossDef":{"para":"A meta-markup language, used to create markup languages such as DocBook.","GlossSeeAlso":["GML","XML"]},"GlossSee":"markup"}}}}}

If I use f.print("mymessage\r\n") the sketch works as expected

[mcspr]

also see #8070

with the examples above...
f.print("...") 360 byte string, plus f.println() results in 0xff 0xff instead of \r \n
f.print("...") 360 byte string, plus f.print('\r') and .fprint('\n') also has the same result
single print("...\r\n") still works though (but, I wonder if there's also a limit when it no longer works)

for failing cases, 0xff is actually 0xff and can be seen on the flash, so I'd guess this is something broken on writes and not something wrong with the reading

00001300: 0100 0800 7c53 4f20 3838 3739 3a31 3938  ....|SO 8879:198
00001310: 3622 2c22 476c 6f73 7344 6566 223a 7b22  6","GlossDef":{"
...
00001390: 476c 6f73 7353 6565 223a 226d 6172 6b75  GlossSee":"marku
000013a0: 7022 7d7d 7d7d 7dff ff7b 2267 6c6f 7373  p"}}}}}..{"gloss
                           ^^ ^^

(looking at binary dump via esptool read_flash 0x300000 0x100000 for something resembling file chunks)

There were no changes to spiffs source itself 2.7.4 and 3.0.0 though, and it is deprecated for a variety of reasons (#7095 plus #7263), so it is a pretty low chance this is going to get fixed.

There are some avenues to explore

• gcc version bump from 4.8.2 to 10.3 might sometimes be an issue (see bad double for loop optimization  #8261), but adding -fno-strict-aliasing to the build does not do anything helpful
• perhaps 79ea883 is related, as it did change the flash write behaviour that spiffs might've relied upon in the previous Core version(s) (ref. cores/esp8266/spiffs_api.cpp and flash hal we use).
  reverting the commit seems to fix the issue

[fabianoriccardi]

I missed your issue, thanks for linking!

I will look at #79ea883 for further insights.

[Bodmer]

I seem to be having the same problem. I have saved data into a SPIFFS file, but after reading ~1kbyte back there are spurious FF's in the data read.

Read back:

E5 D9 5F E1 A8 99 E7 4E FF FF FF B5 29 87 DD 66
                        ^^^^^^^^ incorrect bytes

Correct data:

E5 D9 5F E1 A8 99 E7 4E 1B F5 6D B5 29 87 DD 66
                        ^^^^^^^^ correct data

[Bodmer]

Rolling back from 3.0.x to 2.7.4 fixes the problem so it does appear to be a bug in the latest versions.

[fabianoriccardi]

I can confirm that the issue is on "write" and not in "read" process.

In particular, it seems that the bug is in bool EspClass::flashWrite(uint32_t address, const uint8_t *data, size_t size), and in particular in the else-branch at line

Arduino/cores/esp8266/Esp.cpp

Line 883 in b080c50

} else {

.

If I understood the idea of the algorithm, to write in flash the proper 4-bytes alignment must be guaranteed for both RAM and flash addresses. The issue is that if you try to align one, you will break the other alignment. In that branch you may have a wrong RAM alignment (there is no check about it), so in this case it may fail the writing.

In other words, when you enter that branch, if the flash address is not aligned, you should write a partial 4-bytes block and then re-check the alignment of the start address of remaining data. This may lead to a reallocation of the data on the stack, (it already occurs in flashWriteUnalignedMemory function).

If the maintainer would consider the idea, I can create a pull request.

[mcspr]

Can you provide an example with specific numbers and the call chain that breaks?
BTW, also see RTOS implementation for both u32 that we have and 'generic' void-ptr variant

[fabianoriccardi]

The minimal sketch to reproduce is the following one with core v3.0.2.

#include <FS.h>

void setup() {
  Serial.begin(115200);
  while(!Serial);
  Serial.println();
  
  // You mays need to format the flash before using it
  //SPIFFS.format();

  if(SPIFFS.begin()){
    Serial.println("Filesystem mounted successfully");
  }else{
    Serial.println("Filesystem NOT mounted. System halted");
    while(1) delay(100);
  }
}

void loop() {
  for(int i=0; i<10; ++i){
    Serial.println(i);
    File f = SPIFFS.open("/mytext.txt", "a");
    if(f){
      // Print 200 chars (+2 "\r\n")
      int n = f.println("12345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890");      
      f.close();
      Serial.println(String("I have printed: ") + n );
    } else {
      Serial.println("error");
    }
    delay(500);
  }

  File f = SPIFFS.open("/mytext.txt", "r");
  while(f.available()){
    Serial.println(f.readStringUntil('\n'));
  }
  f.close();
  SPIFFS.remove("/mytext.txt");
}

When you print the file content on serial port, you will see some prints showing "??" instead of "\r\n".

BTW, also see RTOS implementation for both u32 that we have and 'generic' void-ptr variant.

Is this core based on RTOS SDK? I remember, arduino core is based on NONOS SDK... However I have read that implementation, basically the solution is the reallocation of the memory on the stack.

EDIT: I had fixed the previous post by adding the line number, sorry

[fabianoriccardi]

I have pushed a temptative fix that fix the current issue, but it may break other behaviors which I'm not aware of...