esp32 E.openFile stops working after multiple fs.readFile and fs.writeFile

[espruino-discuss3]

Posted at 2018-11-02 by mike_k

First off, thank you to everyone who has contributed to the espruino project, I love it.

I'm running into an issue using an esp32 where, after multiple calls to fs.readFile / fs.writeFile, E.openFile starts returning undefined, and both fs.readFile / fs.writeFile start returning false. Below is an example of fs.writeFile returning false after only 10 writes:

E.srand(4546455454545454);


var fs = require('fs');

function writeData(i){
  if(i < 100){
   var data = Math.random().toString();
   var name = `file_${i}`;
   var res = fs.writeFile(name, data);
   if(res){
     console.log(`wrote... ${name}, ${data}`);
     setTimeout(function(){
       writeData(i + 1);
     }, 100);
   }
   else{
     console.log(`did not write!, ${name}, ${data}`);
   }
  }
}

writeData(0);

I don't think there are any js functions exposed to inspect the situation that is causing this, but please let me know if there is. Also, I'm using a setTimeout above so I don't hit the watchdog timeout, basically simulating if I typed this into the espruino IDE 9 times. below is version information:

{
  "VERSION": "2v00",
  "GIT_COMMIT": "ff35517",
  "BOARD": "ESP32",
  "FLASH": 0, "RAM": 524288,
  "SERIAL": "240ac4af-68e4",
  "CONSOLE": "Serial1",
  "MODULES": "Flash,Storage,heatshrink,fs,net,dgram,tls,http,NetworkJS,Wifi,TelnetServer,crypto,neopixel",
  "EXPTR": 1073483756 }

Also, I've tried variations of this with E.openFile thinking that I could circumvent the issue but the same problem occurs.

Thank you in advanced for the help!!

[espruino-discuss3]

Posted at 2018-11-03 by @allObjects

Could it be that it interferes with the upload of the code? ...because it is executing as part of that task. In first shot, just remove or comment the line with writeData(0);, upload the code, and invoke the method from console. (I do not know your other settings... but in general, putting active code into the upload is not to recommend. Other settings in the IDE may make this an non-issue. Also that it is on a ESP32 chip may render my concern an non-issue, since most of my experience is with the Espruino boards...).

---

Posted at 2018-11-03 by mike_k

I could take another screen shot of this happening using the upload button instead of copy and paste, but this snippet is really just an example of the problem happening in a much, much larger set of modules that I upload to the board.

I was able to narrow down the problem to this section of my code, then made the most base-case example of the problem occurring (as shown in the screenshot) then I ensured it was the problem by running it via:

1. the IDE console,
2. the Upload button via the right side of the IDE,
3. using the Espruino js api tool (which is mainly what I use so I can use es6 and my own watch/compile/upload-only-changes-modules command line tool).

This issue happens in all three cases.

Thank you for the quick reply btw!

---

Posted at 2018-11-03 by Wilberforce

As you are writing to a new file and not closing the last file - you are running out of buffers. If you close the file when you are done with it - or write the same file I don't think you would have an issue.

---

Posted at 2018-11-04 by mike_k

I am emphasizing that I am writing to a brand new file, I’ve tried all three possible ways of uploading, including uploading via console, uploading via the Upload button, as well as uploading via the Espruino command line tool, there are no other ways to upload. I’ve even wrapped the above code in an anonomyous function and executed, even with a setTimout to allow ANY other running scripts to load.

I think @gfwilliams should give his opinion. If he thinks This is developer error, I will gladly continue to debug. I’ve reached a point where the only thing left for me to do is post on the forum, which I will always hold out as long as possible to do. but I’ve reached a point where i’ve narrowed down the problem and provided a example script that demonstrates the issue consistently.

If you feel like this is still developer error, please let me know, and I will forgo the above conversation and move to a different library. Again, thank you for your help.

Also, the first device I began tinkering with was an Espruino board because I wanted to support @gfwilliams ‘s work, because I know how hard he’s worked on this.

---

Posted at 2018-11-04 by @allObjects

@mike_k, I understand your frustration... first you give yourself the run-around, and then everyone else does it to you. As much I agree with that @gfwilliams has most of the insight, there are many others - when it comes to the non-Espruino boards and especially to espressif based boards - who did the ports and spend their time to push Espruino forward on those platforms. This was and is the case for ESP8266 boards, and is even more so for ESP32 boards, and is also mirrored in how @gfwilliams allocates support resources.

So far, I did not use fs or File to that extend that I can answer all questions. I appreciate your thorough exploration of all paths before tapping into time of others. We all know about good and not so good 'forum citizens'...and the one being lazy. Trying and verifying all avenues upfront help debug an issue. Therefore, I think it has nothing to do with how the code gets uploaded or when and how its execution gets started.

The last thing I could think of is that somehow resources are not released. This can happen due to Javascript being single threaded. I think though that you already took care of that by the setTimeout() you use for every next iteration. I doubt that changing - increasing significantly - the timeout time to give the system even more time to do what it has to do to enables writing more than just ten (10) files. It could though be worth - as for a last try - to separate the loop control from the loop body. I do not know how resources acquired in a function are handled when recursion is involved, even with setting the direct self-invocations apart with setTimeout ().

I suggest code like that - in which I even try to reference the loop body function not by symbol reference but string reference - in two different ways: lines 16 and 18. (Not sure if it even matters for Espruino's JavaScript implementation since it runs on the source anyway, and second one is not necessarily the best from a security point of view, since it involves eval().)

EDIT ...this code has a fundamental flaw - thanks @wilberforce to point that out in your following post. Therefore, take the code as sh0wn in my next post, post #8.

var fs = require('fs');

var maxFileNum = 100, fileNum = 0

function writeFile0(i){
   var data = Math.random().toString();
   var name = `file_${i}`;
   var res = fs.writeFile(name, data);
   if (! res) {
     console.log(`did not write!, ${name}, ${data}`);
   }
  }
}

function writeFile() {
  global["writeFile0"](fileNum);
  if (++fileNum < maxFileNum) {
    setTimeout("writeFile()", 100);
  }
}

function onInit() {
  writeFile();
}

setTimeout(onInit, 1000);

Since cutting the writings into separate JavaScript execution streaks withsetTimeout() didn't help, you are welcome to look under the hood and suggest changes to fs component to overcome what ever limitation you obviously discovered... after all, it's all open software...

Btw, with fs there is neither open nor close, only write and append. The open/write/close pattern is implemented with File.

---

Posted at 2018-11-04 by Wilberforce

The issue here is this:

function writeFile() {
  global["writeFile0"](fileNum);
  if (++fileNum < maxFileNum) {
    setTimeout("writeFile()", 100);
  }
}

This is setting up 100 timeouts that will fire nealry at the same time. I think you are expecting them to queue up.

If you get rid of the setTimeout and just call writeFile() I think you will find it will run fine.

---

Posted at 2018-11-05 by @allObjects

...sorry, my bad... by tearing it apart I missed the part of calling the right thing from the right place. Here what I wanted to say:

var fs = require('fs');

var maxFileNum = 100, fileNum = 0;

function writeFile0(i){
   var data = Math.random().toString();
   var name = `file_${i}`;
   var res = fs.writeFile(name, data);
   if (! res) {
     console.log(`did not write!, ${name}, ${data}`);
   }
    setTimeout("writeFile()", 100);
  }
}

function writeFile() {
  if (++fileNum <= maxFileNum) {
    global["writeFile0"](fileNum);
  }
}

function onInit() {
  writeFile();
}
setTimeout(onInit, 1000);

---

Posted at 2018-11-11 by mike_k

Thank you again for your attempt at mitigating the bug that I am facing. There are a few things I would like to cover regarding the code that you've provided, but it's important to note upfront that your changes still result in the same error that I am facing, so I would definitely call it a bug at this point.

First off, your code has an unrecoverable syntax error on line 13:

This was an easy fix, just had to find the syntax issue.

Secondly, accessing a property on an object, regardless if it's global or not, does not need to be accessed via bracket notation just because it has a number at the end, so this may mislead someone to think this makes a difference stumbling upon this issue:

Like you stated, writing anything like the following is not idiomatic javascript, and as you stated, the code involves a security risk if there is anything interpolated into the string in the first argument (because it uses eval under the hood), so I wouldn't do this either (but for the purposes of finding this fs related bug, I will leave it for now):

Without further ado, Here is a screenshot of the resulting syntactically correct code randomly failing to write 14 / 100 files:

I think the most frustrating part is that this issue occurs on both writes and reads (When reading, somethings undefined is returned even though using fs.statSync showns that the file exists and has length).

Touching upon your other statement:

I never stated that fs has a open or close function:

I was stating that I had also attempted an alternative way of writing a file, specifically the functionality below that I did not post originally, because I had stated that "The same problems occur" intermittently:

var file = E.openFile('test_f', 'w');
file.write("wrote data");
file.close();

Thank you again for all your help. I do not think there is any solution to this bug without looking under the hood, so I will file an issue on the github repo and then start digging.

I have written error handling code that retries writing on error, but even then, sometimes it completely stops allowing me from writing to any file what-so-ever, until I execute a full reboot (which won't work in my control flow). So In the end, I think I'm going to have to look at the C code to see if there is anything suspicious occurring.

---

Posted at 2018-11-12 by @allObjects

The open/write/close pattern comment was made upon @wilberforce's post #4.

Accessing a property of an object with property name as string or string variable in square bracket provides the ability to do it dynamic. No different ends, just different means (internally it goes a little bit a different path).

In deed, nothing what so ever tried helps... Ic.

---

Posted at 2018-11-12 by Wilberforce

Hi,
using your original code - I can replicate the issue - it stops after 15 iterations.

I suspected that memory was leaking so intially added a line to print free memory - as I suspected that this was the problem.

https://github.com/espruino/Espruino/blob/e06b3e24de42adb1de6e2cc6046e525880760e7d/libs/filesystem/jswrap_file.c#L277

the issue we have is if there is a failure - 0 is returned and we don't know which error occured or where...

However in debugging - I found a work around.
In the function - calling f=process.memory().free; seems to work. All I can think that is occuring here is it perhaps a garbage collection is occuring - @gfwilliams - any ideas?

var fs = require('fs');
function writeData(i){
  // line below allows this to run!
  f=process.memory().free;
  //console.log(process.memory().free );
  if(i < 40){
   var data = Math.random().toString();
   var name = `file_${i}`;
   var res = fs.writeFile(name, data);
   if(res){
     console.log(`wrote... ${name}, ${data}`);
     setTimeout(function(){
       writeData(i + 1);
     }, 100);
   }
   else{
     console.log(`did not write!, ${name}, ${data}`);
   }
  }
}
writeData(0);

WARNING: gap set scan error code = 103
WARNING: set rssi scan not implemeted yet
wrote... file_0, 0.67312209572
wrote... file_1, 0.85650798066
wrote... file_2, 0.11667447496
wrote... file_3, 0.98353582061
wrote... file_4, 0.55870476251
wrote... file_5, 0.06997160197
wrote... file_6, 0.05838990447
wrote... file_7, 0.31009601164
wrote... file_8, 0.35821451589
wrote... file_9, 0.24528766667
wrote... file_10, 0.51275360515
wrote... file_11, 0.04978711532
wrote... file_12, 0.76238244714
wrote... file_13, 0.11774935718
wrote... file_14, 0.99340898217
wrote... file_15, 0.39304630709
wrote... file_16, 0.48263351408
wrote... file_17, 0.02755051107
wrote... file_18, 0.68166789304
wrote... file_19, 0.64597696841
wrote... file_20, 0.14027355012
wrote... file_21, 0.73948647814
wrote... file_22, 0.17078908633
wrote... file_23, 0.49875334300
wrote... file_24, 0.60857436741
wrote... file_25, 0.09730707253
wrote... file_26, 0.89388832072
wrote... file_27, 0.05864839910
wrote... file_28, 0.26445292693
wrote... file_29, 0.35654671180
wrote... file_30, 0.41393465335
wrote... file_31, 0.37957622081
wrote... file_32, 0.37698324787
wrote... file_33, 0.14988256066
wrote... file_34, 0.04350866705
wrote... file_35, 0.31650148859
wrote... file_36, 0.23993254836
wrote... file_37, 0.81480026189
wrote... file_38, 0.59223879482
wrote... file_39, 0.37215752032
> 

---

Posted at 2018-11-12 by mike_k

@wilberforce that is a solid work-around for now! I am able to execute write operations slightly more predictably now. But disappointingly, the ability to E.openFile still seems to lock up and return undefined after multiple read and write operations:

If I can overcome this last lockup issue that would be excellent! Thank you again!

---

Posted at 2018-11-12 by Wilberforce

@mike_k

As I believe there's only one file buffer you need to stick to either fs or fileopen calls. Every fileopen should be followed by a f.close()

See here:

https://www.espruino.com/File+IO

---

Posted at 2018-11-12 by mike_k

I don’t think I explained myself well enough in my last post above. My apologies.

Every call I make to E.openFile is always followed by an f.close. This works consistently, until a call to E.openFile returns undefined, and i can no longer open and close files, respectively. The above example is explicitly showing the product of this - after running E.openFile, nothing is opened, i.e. undefined is returned (The 3rd-4th lines of the last image demonstrates the execution of the var f, and shows that undefined was assigned to it instead of a file object). Again, I open and close files sequentially, every time I open a file that actually returns a file object, I close right after.

I hope that explains it better. As for the process.memory().free call, I am very grateful you found that work-around! I just hope I can find out why, after opening and closing a file multiple times, and making sure every file I open is indeed closed directly after, eventually causes E.openFile to no longer return anything.

I think the first step in determining why the returned undefined value occurs is to explicitly throw an Out Of Memory error in the C code on the line of code that you’ve provided so it can much more easily be determined that we are simply out of memory vs some other underlying issue:

http://microcosm.app/out/tGLJh

Or, we should make E.openFile configurable in order to enable error throwing when we are out of memory. Again, this will allow developers to choose how to handle and discern whether or not a give api function isn’t working correctly because of lack of memory, or a different bug.

I’d love to hear your thoughts on this, because it wouldn’t cause a lot (if any) of overhead and it gives the developer the choice of how they want to deal with Out Of Memory issues, whether it be via an undefined return value (like it currently does) or an actual thrown error.

Thank you again @wilberforce!!

---

Posted at 2018-11-12 by @gfwilliams

Just tried it here on an official board, and on a Linux build with restricted vars and it works great.

In the function - calling f=process.memory().free; seems to work. All I can think that is occuring here is it perhaps a garbage collection is occuring

Calling process.memory() will cause a garbage collection (in fact process.memory().gc tells you how much got freed).

It looks like the filesystem stuff needs a flat array and is unable to find a large enough flat memory space for it... It is possible it's because of a memory leak...

If it were something that wasn't unlocked you wouldn't expect the behaviour because GC wouldn't be able to free that, but if it were something that was referenced and not unreferenced then that could be it (but it's unlikely as it's very rare that anything outside of core touches references).

OR... it might be because when you use the FAT filesystem on ESP32 the allocation units are 4k? That means each file ends up being quite big.

I guess if there isn't much free RAM available then the data area might get too fragmented to allocate a 4k block of data after a while. I guess by the time GC actually runs, it's too late.

Running GC manually will automatically re-order the free-list, which makes it significantly less likely that things get fragmented in the first place.

---

Posted at 2018-11-12 by @gfwilliams

How about running process.memory() immediately after fs.close() - does that fix it for you?

---

Posted at 2018-11-12 by @gfwilliams

Just to add to this - while I don't seem to be able to reproduce on embedded, by dialling the available memory right down I can make it happen on the Linux build.

It's allocateJsFile that fails, so it's as I thought - it couldn't allocate a big enough flat string buffer for the data.

---

Posted at 2018-11-12 by @gfwilliams

Issue filed here: espruino/Espruino#1559

Actually running process.memory() is a perfectly fine workaround. The issue seems to be when the free list is out of order but no memory is collected by GC. The GC pass returns 0 so Espruino thinks nothing happened (even though the free list is reordered), and never bothers trying to reallocate again.

It should be easy enough to fix.

---

Posted at 2018-11-12 by @gfwilliams

If you take the latest travis builds they should stay working - although it'd be nice to figure out why the free list gets so out of order.

---

Posted at 2018-11-12 by mike_k

@gfwilliams you are awesome. I am unbelievably grateful that you jumped on this bug so quickly. I will try out the latest build later on tonight. Thank you again everyone!