ERROR: Unable to write file : DISK_ERR, leads to Out of Memory errors.

[espruino-discuss]

Posted at 2014-03-06 by DrAzzy

I have a program that reads a pair of DHT's (11 and 22, to compare their readings), shows them on a Nokia 5110 screen, and every ten seconds, records the latest data on the SD card. Every time I go away and leave it, I come back to find something like this on the console:

ERROR: Unable to write file : DISK_ERR
ERROR: Unable to write file : DISK_ERR
ERROR: Unable to write file : DISK_ERR
ERROR: Unable to write file : DISK_ERR
ERROR: Unable to write file : DISK_ERR
ERROR: Unable to write file : DISK_ERR
ERROR: Out of Memory!
ERROR: Out of Memory!
WARNING: Unable to create string as not enough memory
ERROR: Out of Memory!
ERROR:

(with cursor at the end of the word ERROR:)

Using v55 firmware, connecting via bluetooth. After reset, SD card is found to be working normally.

All of the DISK_ERRs come in fairly rapid succession (either all at once, or once per attempted append once the problem manifests). I don't know what the exact timing is, since I've never been watching the console when it happens.

[gfwilliams]

Posted at 2014-03-06 by @gfwilliams

Hmm - It could be that the disk errors are causing Espruino to leak memory (however looking at the code I can't see how), or it could be that Espruino is running low on memory and that's causing the errors?

Could print the value of process.memory().usage each time you read the sensors? It might help to see if the memory usage is rising?

Any chance you could strip your code down (removing the DHT read and LCD write) and see if it still happens?

[espruino-discuss]

Posted at 2014-03-06 by DrAzzy

I'll try to strip it down into a minimal example that exhibits the behavior.

While it was running, I checked process.memory() and it was steady at 900 used.

[gfwilliams]

Posted at 2014-03-06 by @gfwilliams

Hmm, that should be ok then... I wrote some simple code to append to a file, and the pulled the SD card out (producing DISK_ERR errors), and that didn't cause the memory usage to rise...

[espruino-discuss]

Posted at 2014-03-07 by DrAzzy

The DISK_ERR issue itself is trivial to reproduce:

var fs=0;
function randint(max) { return Math.round(Math.random()*max); }



function onInit() {
    digitalWrite(A14,1);
    setTimeout("doInit();",2000);
}

function doInit() {
    digitalWrite(A14,0);
    fs=require("fs")
    setInterval(function(){dologs();},10000);

}

function dologs() {
    digitalWrite(A15,1)
    var temp=randint(10);
    fs.appendFile("testlog.log","ASDF,"+temp.toString()+",Time,"+getTime().toFixed()+"\n");
    digitalWrite(A15,0)
}

onInit();

This will run for a while, until eventually, every attempt to write results in DISK_ERR. This itself is a Bad Thing.

However, it does not run out of memory!

So why does it run out of memory when running the full setup?

var g = 0;
var d = 0;
var inits=new Uint8Array([0,0,0,0]);
var t=-1;
var rh=-1;
var t2=-1;
var rh2=-1;
var line1="";
var line2="";
var fs;
var activepin="";


function onInit() {
    digitalWrite(A14,1);
    digitalWrite(A13,1);
    setTimeout("doInit();",2000);
}

function doInit() {
    digitalWrite(A15,1);
    fs=require("fs")
    SPI3.setup({ baud: 1000000, sck:B3, mosi:B5 });
    digitalWrite(A13,0);
    g=require("PCD8544").connect(SPI3,B6,B7,B4, function() {
        g.clear();
        g.drawString("LCD OK",0,0);
        g.drawLine(0,10,84,10);
        g.flip();
        digitalWrite(A15,0);
        setTimeout("inits[0]=1;endInit();",100);
    });
    d=require("DHT11").connect(C10)
    d.read(function(a){ t=a.temp; rh=a.rh; inits[1]=1;endInit();});
    e=require("DHT22").connect(C11)
    setTimeout(function(){ e.read(function(a){ t2=a.temp; rh2=a.rh; inits[2]=1;endInit();});},2000);

}

function endInit() {
    if (inits[0]==1 && inits[1]==1 && inits[2]==1 && inits [3]==0) 
    {
        inits[3]=1;
        digitalWrite(A14,0);
        g.clear();
        g.drawString("Init OK!",0,0);
        g.flip();
        setInterval(function() {doMeasure();},5000);
        setTimeout(function(){setInterval(function(){doMeasure2();},5000);},2500);
        setInterval(function(){dologs();},30000);
    }
}

function doMeasure() {
    d.read(function(a) {
        if (a.rh!=-1 && a.temp < 50) {
        	rh=a.rh;
        	t=a.temp;
        }
        updateLCD();
    });
}

function dologs() {
    fs.appendFile("timetemp.log","DHT11,"+t.toString()+","+rh.toString()+",DHT22,"+t2.toString()+","+rh2.toString()+",Time,"+getTime().toFixed()+"\n");
}

function doMeasure2() {
    e.read(function(a) {
        if (a.rh!=-1 && a.temp < 50) {
            rh2=a.rh;
            t2=a.temp;
        } 
        updateLCD();
    });
}

function updateLCD() {
    g.clear();
    if (t!=-1) { 
        g.drawString("Temp: "+t.toString()+"C",0,0);
        g.drawString("RH: "+rh.toString()+"%",0,10);
        g.drawString("Temp: "+t2.toString()+"C",0,20);
        g.drawString("RH: "+rh2.toString()+"%",0,30);
    } else {
        g.drawString("DHT11 not",0,0);
        g.drawString("working!",0,10);
    }
    g.drawString(line1,0,20);
    g.drawString(line2,0,30);
    g.flip();
}
onInit();

All I can think of is that this DISK_ERR disrupts other things happening at the same time, like DHT read or LCD update.

Unfortunately, I've never been able to catch it between the first time it gives the DISK_ERR and when it runs out of memory, in order to see if it's leaking memory every time, or whether it survives until the error happens at a critical moment.

[espruino-discuss]

Posted at 2014-03-07 by Frida

setTimeout("doInit();",2000);

change to:
setTimeout(doInit,2000);

then it works on my Espruino.
setTimeout() don't like a string, then it don't call doInit() and therefor it don't require fs and we get DISK_ERR
Edit:
It only reached 102 before DISK_ERR came back. Then there was a 30 DISK_ERR before continuing.

[espruino-discuss]

Posted at 2014-03-07 by Frida

Now I have it running again, and right now it reached to 400 logs to the file without error.
I also changed the order of the objects. It seems to Espruino dislike forward references.

[espruino-discuss]

Posted at 2014-03-07 by Frida

With 1 sec. log it failed at
1493ASDF,1,Time,1595
1751ASDF,6,Time,1884
then a little later
1842ASDF,7,Time,2016
1843ASDF,7,Time,2017
1844ASDF,1,Time,2017
1845ASDF,6,Time,2017
1846ASDF,2,Time,2017
1847ASDF,1,Time,2017
1848ASDF,3,Time,2017
1849ASDF,2,Time,2017
1850ASDF,4,Time,2017
1851ASDF,1,Time,2018
1852ASDF,4,Time,2018
1853ASDF,3,Time,2018
1854ASDF,7,Time,2018
1855ASDF,1,Time,2018
1856ASDF,3,Time,2018
1857ASDF,4,Time,2018
1858ASDF,1,Time,2018
1859ASDF,4,Time,2018
1860ASDF,7,Time,2018
1861ASDF,10,Time,2018
time is still 1 sec.

[espruino-discuss]

Posted at 2014-03-07 by DrAzzy

Hm.

On my Espruino, onInit and doInit are DEFINITELY running - if they weren't, it wouldn't work at all. On my Espruino, I've always been able to put strings into setTimeout/setInterval. The IDE warns me that it's "evil", but it works fine*. What I didn't realize is that you could just pass it the name of a function, unquoted, and have it call that function with no arguments! I thought you had to do:
setTimeout(function(){doInit();},2000);

So in your case, it sorts itself out after enough disk errors happen? I don't think it was coming back to life for me, will check logs tonight.

*Note that I have not tested whether this "evil" evaluation has resulted in my eternal damnation; testing this seems like a real chore.

[espruino-discuss]

Posted at 2014-03-09 by DrAzzy

I've determined that the out of memory issue can happen without logging. So I think there is some condition in which my DHT module explodes. Investigations are ongoing.

However, there is still the issue with the SD card getting unhappy and producing DISK_ERRs, which happens when just logging gibberish. Do you have any thoughts on how to debug this further?

[espruino-discuss]

Posted at 2014-03-10 by DrAzzy

And yet, here's a log clearly showing that once the disk errors start, the memory problems begin - I am back to being convinced this is an Espruino bug, as the system was stable for approximately one hour, reporting stable memory usage, then the instant it started disk erroring, it started leaking memory every time it measured the DHT's.

52
952
952
952
952
952
952
952
952
952
ERROR: Unable to write file : DISK_ERR
895
ERROR: Unable to write file : DISK_ERR
854
ERROR: Unable to write file : DISK_ERR
775
ERROR: Unable to write file : DISK_ERR
764
ERROR: Unable to write file : DISK_ERR
707
ERROR: Unable to write file : DISK_ERR
627
ERROR: Unable to write file : DISK_ERR
618
ERROR: Unable to write file : DISK_ERR
560
482
413
356
277
210
152
74
ERROR: Out of Memory!
ERROR: Out of Memory!
WARNING: Unable to create string as not enough memory
at line 1 col 25
{dht.onread(dht.endRead());}
                         ^
in function called from system
Execution Interrupted during event processing - clearing all timers and watches.
>process.memory()
={"free":997,"usage":803,"total":1800,"history":1,"stackEndAddress":536909500,"flash_start":134217728,"flash_binary_end":134438664,"flash_code_start":134443008,"flash_length":262144}
> 

The code that's generating this:

var g = 0;
var d = 0;
var inits=new Uint8Array([0,0,0,0]);
var curdht=false;
var t=-1;
var rh=-1;
var t2=-1;
var rh2=-1;
var line1="";
var line2="";
var fs;
var activepin="";

function onInit() {
    digitalWrite(A14,1);
    digitalWrite(A13,1);
    setTimeout("doInit();",2000);
}

function doInit() {
    digitalWrite(A15,1);
    fs=require("fs")
    SPI3.setup({ baud: 1000000, sck:B3, mosi:B5 });
    digitalWrite(A13,0);
    g=require("PCD8544").connect(SPI3,B6,B7,B4, function() {
        g.clear();
        g.drawString("LCD OK",0,0);
        g.drawLine(0,10,84,10);
        g.flip();
        digitalWrite(A15,0);
        setTimeout("inits[0]=1;endInit();",100);
    });
    d=require("DHT11dev").connect(C10)
    d.read(function(a){ t=a.temp; rh=a.rh; inits[1]=1;endInit();});
    e=require("DHT22dev").connect(C11)
    setTimeout(function(){ e.read(function(a){ t2=a.temp; rh2=a.rh; inits[2]=1;endInit();});},2000);

}

function endInit() {
    if (inits[0]==1 && inits[1]==1 && inits[2]==1 && inits [3]==0) 
    {
        inits[3]=1;
        digitalWrite(A14,0);
        g.clear();
        g.drawString("Init OK!",0,0);
        g.flip();
        setInterval(function() {console.log(process.memory().free);curdht=!curdht;if(curdht){doMeasure();}else{doMeasure2();}},5000);
        setInterval(function(){dologs();},30000);
        setBusyIndicator(A13);
    }
}

function doMeasure() {
    d.read(function(a) {
        if (a.rh!=-1 && a.temp < 50) {
        	rh=a.rh;
        	t=a.temp;
        }
        updateLCD();
    });
}

function dologs() {
    fs.appendFile("timetemp2.log","DHT11,"+t.toString()+","+rh.toString()+",DHT22,"+t2.toString()+","+rh2.toString()+",Time,"+getTime().toFixed()+"\n");
}

function doMeasure2() {
    e.read(function(a) {
        if (a.rh!=-1 && a.temp < 50) {
            rh2=a.rh;
            t2=a.temp;
        } 
        updateLCD();
    });
}

function updateLCD() {
    g.clear();
    if (t!=-1) { 
        g.drawString("Temp: "+t.toString()+"C",0,0);
        g.drawString("RH: "+rh.toString()+"%",0,10);
        g.drawString("Temp: "+t2.toString()+"C",0,20);
        g.drawString("RH: "+rh2.toString()+"%",0,30);
    } else {
        g.drawString("DHT11 not",0,0);
        g.drawString("working!",0,10);
    }
    g.drawString(line1,0,20);
    g.drawString(line2,0,30);
    g.flip();
}

Does anyone have any thoughts on what might be going on? Is there any way to get some information about where all that memory is going when it starts to fail?

Using Espruino v55.

[gfwilliams]

Posted at 2014-03-10 by @gfwilliams

That's pretty strange... You get the memory leak with the disk error:

627
ERROR: Unable to write file : DISK_ERR
618
ERROR: Unable to write file : DISK_ERR
560
482
413
356

But then the disk errors stop and you're still losing memory! You could try typing trace(), which dumps the internal datastructures. I guess you might be able to find something in there that hinted at where the memory was going...

If you could try and get the simplest possible piece of code that still got the memory leaks then that'd really help matters.

With the DISK_ERR, I'm unsure what to do as it's the filesystem lib that's failing and when I have tried it, it does recover eventually - the development version (or 1v56 when it is released) now returns false is appendFile fails, so you could try again if needed.

By the way, Using strings in setInterval/etc it's really evil in Espruino - it's actually pretty efficient. It's just that jslint (which is what does the warnings) thinks it is and I haven't got around to convincing it otherwise :)

[espruino-discuss]

Posted at 2014-03-11 by DrAzzy

Got a trace of it just before it exploded (down to 61 free at start). Clearly a repetitive structure - but uh... I can't make sense of the trace... What are these multiplied things?
http://drazzy.com/espruino/trace.txt

Another one, where the trace was taken right after the problem first manifested.
http://drazzy.com/espruino/trace2.txt

[gfwilliams]

Posted at 2014-03-11 by @gfwilliams

Thanks - that's really helpful... So it looks like there are a whole bunch of setTimeouts coming from the DHT11 module, but I have no idea why!

The only thing I can think is that somehow the RTC is getting really confused and the value from getTime actually jumps backwards at some point (and that might explain why you get the DISK_ERR).

Please can you also log the value from getTime() alongside process.memory()?

How long does this happen after the last hard reset? From the logs it looks like both times have been after around 4 hours? Do you think it's been around that amount of time in each case?

[gfwilliams]

Posted at 2014-03-11 by @gfwilliams

I've discovered a pretty nasty problem I think that could explain your issues. After 65535 seconds, the RTC goes into the second 16 bit word, and I wasn't combining the two 16 bit words properly - so time would suddenly jump back at that point.

It should be fixed in 1v56 now

[gfwilliams]

Posted at 2014-03-12 by @gfwilliams

I'm still trying to track this down - something happens after around 8000 seconds, and the RTC reports the correct time, but getTime() reports around 16000 secs

[espruino-discuss]

Posted at 2014-03-18 by DrAzzy

Happened really fast the first time, now seems to be running stable for a while
Edit: Now closing in on 5 hrs running continuously. Heading to bed.

All of these errors were appearing in rapid succession, meaning it was trying to log much more frequently than it should have been - the onslaught was such that the trace and everything else got pushed out. Is there a way to make the IDE log to a file, so I wouldn't miss the results of trace() and the events surrounding the initial event?

In any event, there is no way that the espruino was running for 44494 seconds, nor had it been running for ~25k seconds when the failure occurred.

!!?!?!

http://drazzy.com/espruino/v58devfailure.txt

I'm rather confused by the early failure, followed by a very stable run....

[gfwilliams]

Posted at 2014-03-18 by @gfwilliams

Yes... I had that once - but then it went away. I wonder whether it was something strange to do with the firmware update....

Let me know whether it happens again though (and if you find a way to reproduce it). Glad it's looking more stable now!

[espruino-discuss]

Posted at 2014-03-18 by DrAzzy

Failed at some point during the night with the same symptom. Again, by the time I'd found it, the original trace() was long since pushed off the console, and disk errors coming rapidly while the getTime increased far too fast. Last log entry was at 28802.

[gfwilliams]

Posted at 2014-03-18 by @gfwilliams

Strange. I've been running it overnight here (not with filesystem writes, but with a clock using setInterval) and it's spot on :(

[espruino-discuss]

Posted at 2014-03-18 by DrAzzy

Yeah, I've only seen it when I'm doing fs writes. It's as if the SD card failure breaks the timer somehow...

Seems to work fine just sitting there reading dht's.

Edit: Just got another failure, this one much faster - and I got the whole trace this time because it froze entirely at the end

http://drazzy.com/espruino/v58devfailure2.txt

(note that I'd created a demo array to show my friend the WS2812's, that's why there's a graphics object in the trace)

[gfwilliams]

Posted at 2014-03-19 by @gfwilliams

Thanks - just wanted to check - are you using setDeepSleep at all?

[espruino-discuss]

Posted at 2014-03-19 by DrAzzy

Nope, no deep sleep.

[espruino-discuss]

Posted at 2014-03-21 by DrAzzy

The timer bug can be reproduced with this code:

var fs;
var interv;
var t=-1;
var rh=-1;



function onInit() {
    setTimeout("doInit();",2000);
}

function doInit() {
    fs=require("fs");
    fs.appendFile("timetemp.log","Espruino restarted")
    interv=setInterval(function(){dologs();},5000);
    setBusyIndicator(A13);
}

function dologs() {
    console.log("trying to log..."+getTime().toFixed());    
    var ti = getTime();
    if (!fs.appendFile("diskerrator.log","DHT11,"+t.toString()+","+rh.toString()+",Time,"+getTime().toFixed()+"\n")){
        console.log("FAIL before "+ti+" after "+getTime());
    }
}


save();

Ran it overnight, and woke up to it broken. Manually cleared the interval, and typed getTime() a few times. These were typed a couple of seconds apart at most:

ERROR: Unable to write file : DISK_ERR
FAIL before 45778185.87560272216796 after 45778190.38722991943359
trying to log...45778199
ERROR: Unable to write file : DISK_ERR
FAIL before 45778211.53864669799804 after 45778216.05158138275146
trying to log...45778225
ERROR: Unable to write file : DISK_ERR
FAIL before 45778237.20124530792236 after 45778241.71224975585937
trying to log...45778250
ERROR: Unable to write file : DISK_ERR
FAIL before 45778262.85095405578613 after 45778267.36160087585449
trying to log...45778276
ERROR: Unable to write file : DISK_ERR
FAIL before 45778288.36543083190917 after 45778292.84815883636474
trying to log...45778302
ERROR: Unable to write file : DISK_ERR
FAIL before 45778314.20237731933593 after 45778316.91917991638183
trying to log...45778319
ERROR: Unable to write file : DISK_ERR
FAIL before 45778324.45648479461669 after 45778326.43975925445556
trying to log...45778329
ERROR: Unable to write file : DISK_ERR
FAIL before 45778333.97615909576416 after 45778336.01252174377441
clearInterval(inter);
=undefined
getTime();
=45802702.42679214477539
getTime();
=45814433.28411769866943
getTime();
=45828450.28250503540039
reset();
=undefined
 _____                 _ 
|   __|___ ___ ___ _ _|_|___ ___ 
|   __|_ -| . |  _| | | |   | . |
|_____|___|  _|_| |___|_|_|_|___|
          |_| http://espruino.com
 1v58 Copyright 2014 G.Williams

=undefined
>getTime();
=46298892.14406204223632
>getTime();
=46307856.84639739990234

(in above, I had to remove the > prompt, otherwise the forum mangled it)

Last entries in the log:

DHT11,-1,-1,Time,11087
DHT11,-1,-1,Time,11092
DHT11,-1,-1,Time,11097
DHT11,-1,-1,Time,11102
DHT11,-1,-1,Time,11107
DHT11,-1,-1,Time,11112
DHT11,-1,-1,Time,11117
DHT11,-1,-1,Time,11122
DHT11,-1,-1,Time,11127
DHT11,-1,-1,Time,11132
DHT11,-1,-1,Time,11137
DHT11,-1,-1,Time,11142
DHT11,-1,-1,Time,11147
DHT11,-1,-1,Time,11152
DHT11,-1,-1,Time,11157
DHT11,-1,-1,Time,12697
DHT11,-1,-1,Time,12697
DHT11,-1,-1,Time,12697
DHT11,-1,-1,Time,12697
DHT11,-1,-1,Time,12697
DHT11,-1,-1,Time,12697
DHT11,-1,-1,Time,16339
DHT11,-1,-1,Time,16339
DHT11,-1,-1,Time,16339
DHT11,-1,-1,Time,16339
DHT11,-1,-1,Time,16339

[gfwilliams]

Posted at 2014-03-21 by @gfwilliams

You know you can just wrap code in three backtick marks? I just edited your post to add it.

Thanks for cutting it down - I'll try that code out and see what I can get to happen with it.

[espruino-discuss]

Posted at 2014-03-21 by DrAzzy

Yeah - I knew about the backticks (and used them for the js code - or I thought I did), but didn't think to use it on the logs - I was in a hurry since I was posting it while not before I left for work.

What's strange is how it gets 11 writes off (in two bursts) shortly after things have started going off the rails.

[gfwilliams]

Posted at 2014-03-21 by @gfwilliams

Right - just reproduced. Mine did it early too:

trying to log...4033
trying to log...4038
trying to log...4043
trying to log...4050
ERROR: Unable to write file : DISK_ERR
FAIL before 4052.196215629577636718 after 4060.322003364562988281
trying to log...4078
ERROR: Unable to write file : DISK_ERR
FAIL before 4080.756432533264160156 after 4088.670434951782226562
trying to log...4095
ERROR: Unable to write file : DISK_ERR
FAIL before 4097.461118698120117187 after 4105.502131462097167968

I'll see what I can do about fixing this next week.

[gfwilliams]

Posted at 2014-03-22 by @gfwilliams

Just a thought - this will be some issue with the code that keeps the system tick timer in sync with the RTC.

As a workaround, try setDeepSleep (1) and power from a charger/battery so it enters sleep. That will almost certainly solve your problems.

It also explains why one of mine has been running all week and is still keeping good time.

[gfwilliams]

Posted at 2014-03-24 by @gfwilliams

Could you give this a go please? http://www.espruino.com/binaries/git/commits/e85fa5a013c3a1469635b92e12a35591eb2589d8

I've been running it for the past 6 hours or so with your logger and it appears to be fine.

[espruino-discuss]

Posted at 2014-03-25 by DrAzzy

So far it's been running over night without issue. Will keep letting it run.

[gfwilliams]

Posted at 2014-03-25 by @gfwilliams

Wohoo! 1v59 (just released) has the fix in too.