Memory leak... ESP8266 + 0-length response

[espruino-discuss]

Posted at 2015-04-20 by DrAzzy

I've got my voice recognition program working on a Pico, using EasyVR2.0.
It works - I can say "Switch Desk" and it switches the desk light on/off, etc by sending an http request over the ESP8266.

Unfortunately, there's a problem. Every time it processes a command, it loses 100 jsvars. It's definitely something I'm doing, but I can't figure out if it's a bug in my code that's just my fault, or

I can't read the trace() output effectively - I see tons of stuff duplicated, and I don't know which is the junk that's my user code, and which is an artifact of the output format.

EasyVR.js (idea is - you tell module to setRecognize(), then that sets the timeout. The EasyVR replies that that was successful, triggering the command to start listening. Noise will result in either an error response, or a result response (if the noise was me saying "Nixie" or w/e), and then fires the appropriate callback

exports.connect = function(serial,onCm,onTo,onEr) {
    return new EasyVR(serial,onCm,onTo,onEr);
};

function EasyVR(ser,onCm,onTo,onEr) {
  this.ser = ser;
  this.onCommand=onCm;
  this.onTimeout=onTo;
  this.onErr=onEr;
  this.ser.on('data',this.onData.bind(this));
  this.stop();
  this.vrstate=-1;
  this.stsr='o';
  this.rcvv="";
  this.tout=0;
  this.lstC='';
}

EasyVR.prototype.argchar=function(val) {
	if (val<-1 || val > 31) {throw "Bad arg";}
	return String.fromCharCode(0x41+val);
};

EasyVR.prototype.chararg=function(chr) {
	return chr.charCodeAt(0)-0x41;

}; 

EasyVR.prototype.onData=function(data) {
	//this=evr;
	
	console.log("serial data watch: "+data);
	var rcv=data.charCodeAt(0);
	console.log("serial data: "+rcv);
	if (rcv>0x60) {
		console.log("status");
		//console.log("serial lookup: "+temp);
		if (this.sts_idx[data]["len"]) {
			this.stsr=data;
			this.ser.print(' ');
			console.log("need to get data")
		} else {
			console.log("no data to get")
			this.sts_idx[data]["cb"].bind(this)();
		}
	} else {
		console.log("data");
		this.rcvv+=data;
		if (this.rcvv.length>=this.sts_idx[this.stsr]["len"]){
		    console.log("running callback "+this.sts_idx[this.stsr]["cb"]);
			this.sts_idx[this.stsr]["cb"].bind(this)();
			this.rcvv="";
			this.stsr='o';
		} else {
		    console.log("need more data");
			this.ser.print(' ');
		}
	}

};
EasyVR.prototype.sts_idx={
	"o":{len:0,cb:function(){
		console.log('STS_SUCCESS');
		console.log(this.lstC);
		if (this.lstC=='o')  { 
			console.log(this.vrstate);
			if (this.vrstate!=-1) {
				console.log("kicking off recognize");
				this.sendCmd('d',this.vrstate);
			}
		}
	}},
	"t":{len:0,cb:function() {
		console.log('STS_TIMEOUT');
		if (this.vrstate!=-1){
			console.log("calling onTimeout callback");
			this.onTimeout(this.vrstate);
			this.vrstate=-1;
		}
	}},
	"v":{len:0,cb:function() {
		console.log('STS_INVALID '+this.rcvv);
		if (this.vrstate!=-1){
			this.vrstate=-1;
		}
	}},
	"i":{len:0,cb:function() {
		console.log('STS_INTERR '+this.rcvv);
		if (this.vrstate!=-1){
			this.vrstate=-1;
		}
	}},
	"e":{len:2,cb:function() {
		console.log('STS_ERROR '+this.rcvv);
		if (this.vrstate!=-1){
			console.log("calling onErr callback");
			var tem=this.vrstate;
			this.vrstate=-1;
			this.onErr(tem);
		}
	}},
	"s":{len:1,cb:function() {
		console.log('STS_SIMILAR '+this.rcvv);
		if (this.vrstate!=-1){
			console.log("calling onErr callback");
			var tem=this.vrstate;
			this.vrstate=-1;
			this.onErr(tem);
		}
	}},
	"r":{len:1,cb:function() {
		console.log('STS_RESULT '+this.rcvv);
		if (this.vrstate!=-1){
			console.log("calling onCommand");
			console.log(r);
			var rt = this.onCommand(this.vrstate,this.chararg(this.rcvv));
			this.vrstate=-1;
			if (rt.type!==undefined) {
				this.setRecognize(rt.type,rt.timeout);
			}
		}
	}}
};


EasyVR.prototype.setRecognize=function(type,to) {
	if (this.tout) {
		clearTimeout(this.tout);
		this.tout=0;
	}
	this.vrstate=type;
	this.timeout(to);
};

EasyVR.prototype.sendCmd=function(cmd,arg) {
	//lastCmd=[cmd,arg];
	this.ser.print(cmd);
	console.log("Sending command: "+cmd);
	this.lstC=cmd;
	if (arg!==undefined){console.log("With arg: "+this.argchar(arg));this.ser.print(this.argchar(arg));}
};

EasyVR.prototype.stop=function(){
	this.sendCmd('b');
};
EasyVR.prototype.timeout=function(arg) {
	this.sendCmd('o',arg);
};

EasyVR.prototype.setStrict=function(arg) {
	this.sendCmd('v',E.clip(arg,1,5));
};

[espruino-discuss]

Posted at 2015-04-20 by DrAzzy

My code:

var ocm=function(menu,option) {
  console.log("menu:"+menu+" option: "+option);
  if (menu==1) {
    if (option==0) {
      console.log("LIGHTS ON");
      //do lights on calls
    } else if (option==1) {
      console.log("LIGHTS OFF");
      //do lights off calls
    } else if (option==2) {
      console.log("SWITCH :");
      digitalWrite(LED1,1);
      return {type:2,timeout:15};
    } else if (option==3) {
      console.log("DESK :");
      digitalWrite(LED1,1);
      return {type:3,timeout:15};
    } else if (option==4) {
      console.log("NIXIE :");
      digitalWrite(LED1,1);
      return {type:4,timeout:15};
    }
  } else {
    if (menu==2) { // toggle a fargo or RF controlled device
      console.log("toggle device "+option);
      if (option < 8) {
        setFargo(option,!fargo[option]);
        console.log("set fargo"+option);
      } 
    } else if (menu==3) { // control desk lamp
      console.log("desk lamp "+option);
    } else if (menu==4) { // control nixie clock
      if (option==0) { //clock on
        setDesk("nixs=1;uplcd();");
      } else if (option==1) { //clock off
        setDesk("nixs=0;uplcd();");
      } else if (option==2) { //time
        setDesk("nixs=1;MnuS=0;MnuO=0;uplcd();");
      } else if (option==3) { //temp
        setDesk("nixs=1;MnuS=0;MnuO=1;uplcd();");
      } else if (option==4) { //humidity
        setDesk("nixs=1;MnuS=0;MnuO=2;uplcd();");
      //} else if (option==5) { //pressure
      //  setDesk("nixs=1;MnuS=0;Mnu0=3;uplcd();")
      } 
    }
  }
  digitalWrite(LED1,0);
  return {type:1,timeout:0};
  
};

var otm=function(){
  digitalWrite(LED1,0);
  this.setRecognize(1,0);
};






//My standard fargo network commands
fargosturl="http://192.168.2.12/fargostatus.php";
dateurl="http://192.168.2.12/date.php";
fargourl="http://192.168.2.14/api/relay/";
deskurl="http://192.168.2.16/code.run?code=";
fargo=new Uint8Array(8);


function setDesk(command) {
  console.log("setDesk:"+deskurl+command);
	require("http").get(deskurl+command, function(res) {
		res.on('close',function () {
			if(this.code!=200) {
				console.log("Error commanding desklamp/nixie: "+this.code);
            }
		});
	});
  console.log("desk command"+command);
}


function getFargostatus() {
	var fargost="";
	require("http").get(fargosturl, function(res) {
		res.on('data',function (data) {fargost+=data;});
		res.on('close',function() {var tfs=JSON.parse(fargost); vtfs=tfs; for (var i=0;i<8;i++) { fargo[i]=tfs.relaystate[i].state;} if(MnuS==3){uplcd(1);}});
	});
}

function setFargo(relay,state) {
	var postfix = (state) ? "/on":"/off";
	require("http").get(fargourl+(relay+1).toString()+postfix, function(res) {
		res.on('close',function () {
			if(this.code!=200) {
				fargo[relay]=state;
			}
		});
	});
}



function getDate() {
	var date="";
	require("http").get(dateurl, function(res) {
		res.on('data',function (data) {date+=data;});
		res.on('close',function() {clk=new Clock(date);});
	});
	//delete getDate;
}

function onInit() {
  Serial1.setup(9600,{tx:B6,rx:B7});
  evr=require("easyvr").connect(Serial1,ocm,otm,otm);
  Serial2.setup(9600, { rx: A3, tx : A2 });
  wifi = require("ESP8266WiFi").connect(Serial2, function(err) {
  if (err) throw err;
  wifi.reset(function(err) {
    if (err) throw err;
    console.log("Connecting to WiFi");
    wifi.connect("TwilightZone","L0st1nTheZ0ne", function(err) {
      if (err) throw err;
      console.log("Connected");
      // Now you can do something, like an HTTP request
      evr.setRecognize(1,0);
      setTimeout(getFargostatus,1000);
      setInterval(getFargostatus,30000);
    });
  });
});
  
}

Trace attached

Thanks to anyone who can see what's getting duplicated in memory and eating up memory....

Attachments:

• trace.txt

[gfwilliams]

Posted at 2015-04-20 by @gfwilliams

Any chance you could do a trace, process a few commands, and then do another one and attach both?

It'd make it easier to diff them...

[espruino-discuss]

Posted at 2015-04-20 by DrAzzy

Traces before and after turning my desk light off and on with my voice. (Switch, option 4 on the submenu)

Attachments:

• trace_after.txt
• trace_before.txt

[gfwilliams]

Posted at 2015-04-20 by @gfwilliams

Just looked and I'm pretty sure that in this case it's because there are two open HTTP connections. It's odd because the connection: close header was sent so the server should have just closed the connection right away.

This is done with the ESP8266?

[espruino-discuss]

Posted at 2015-04-20 by DrAzzy

Yup, ESP8266 on Pico.

[espruino-discuss]

Posted at 2015-04-21 by DrAzzy

Any ideas on what's going on here?

I'd really like to get this working; I'm dead in the water currently on this project right now because of this memory leak, which I really don't know how to approach fixing.

[gfwilliams]

Posted at 2015-04-22 by @gfwilliams

Well, it's because there are still open HTTP connections - However I don't know whether that is because the server isn't closing the connection, or because somehow Espruino isn't responding to what the ESP8266 says.

What happens if you check the memory usage one minute later? If it's lower then it may well be that the server isn't closing the connection.

And you're not getting any errors reported? I guess you could use the wifi.at.debug() to see if the ESP8266 really is reporting that the connections are closed.

Does res.on('close', always end up getting called for every HTTP request? If it is and the request still isn't closed then there's some bigger issue.

[espruino-discuss]

Posted at 2015-04-27 by DrAzzy

(sorry for multipost, forum is breaking edit window every time I scroll in it...)

res.on('close',...) is not being called.

Ever, for any of the requests

function setFargo(relay,state) {
  console.log("setFargo called");
	var postfix = (state) ? "/on":"/off";
	require("http").get(fargourl+(relay+1).toString()+postfix, function(res) {
		res.on('close',function () {
          console.log("onClose called");
			if(this.code==200) {
				fargo[relay]=state;
			}
		});
	});
}

Here's a log of that "onClose called" is never recorded. I also added that to the more boring ones, and saw the same behavior :-/ So yeah - it looks like on close event isn't being handled on the ESP8266:

[espruino-discuss]

Posted at 2015-04-27 by DrAzzy

setFargo called
["AT+CIPSTART=0,\"TCP\",\"192.168.2.14\",80\r\n"
set fargo4
Sending command: o
With arg: A
serial data watch: o
serial data: 111
status
no data to get
STS_SUCCESS
o
1
kicking off recognize
Sending command: d
With arg: B
] "\r\n" <--- "\r\n"
] "OK" <--- "OK"
] "OK\r\n" <--- "\r\n"
] "Linke" <--- "Linke"
] "Linked" <--- "d"
] "Linked\r\n" <--- "\r\n"
["AT+CIPSEND=0,64\r\nGET /api/relay/5/off HTTP/1.0\r\nUser-Agent: Espruino 1v77\r\nConnec"
] ">" <--- ">"
] "> " <--- " "
] "> \r" <--- "\r"
] "\nSEN" <--- "\nSEN"
] "SEND " <--- "D "
] "SEND OK" <--- "OK"
] "SEND OK\r" <--- "\r"
] "\n" <--- "\n"
["AT+CIPSEND=0,35\r\ntion: close\r\nHost: 192.168.2.14\r\n\r\n"
] ">" <--- ">"
] "> " <--- " "
] "> \r" <--- "\r"
] "\nSE" <--- "\nSE"
] "SEND" <--- "ND"
] "SEND O" <--- " O"
] "SEND OK\r" <--- "K\r"
] "\n\r\n+" <--- "\n\r\n+"
] "+IP" <--- "IP"
] "+IPD," <--- "D,"
] "+IPD,0,9" <--- "0,9"
] "+IPD,0,98:H" <--- "8:H"
] "+IPD,0,97:TTP" <--- "TTP"
] "+IPD,0,94:/1." <--- "/1."
] "+IPD,0,91:1 20" <--- "1 20"
] "+IPD,0,87:0 O" <--- "0 O"
] "+IPD,0,84:K\r\nA" <--- "K\r\nA"
] "+IPD,0,80:cce" <--- "cce"
] "+IPD,0,77:ss-C" <--- "ss-C"
] "+IPD,0,73:ont" <--- "ont"
] "+IPD,0,70:rol" <--- "rol"
] "+IPD,0,67:-All" <--- "-All"
] "+IPD,0,63:ow-" <--- "ow-"
] "+IPD,0,60:Orig" <--- "Orig"
] "+IPD,0,56:in:" <--- "in:"
] "+IPD,0,53: *\r\n" <--- " *\r\n"
] "+IPD,0,49:Con" <--- "Con"
] "+IPD,0,46:nec" <--- "nec"
] "+IPD,0,43:tion" <--- "tion"
] "+IPD,0,39:: c" <--- ": c"
] "+IPD,0,36:lose" <--- "lose"
] "+IPD,0,32:\r\nC" <--- "\r\nC"
] "+IPD,0,29:ache" <--- "ache"
] "+IPD,0,25:-Co" <--- "-Co"
] "+IPD,0,22:ntr" <--- "ntr"
] "+IPD,0,19:ol: " <--- "ol: "
] "+IPD,0,15:max" <--- "max"
] "+IPD,0,12:-age" <--- "-age"
] "+IPD,0,8:=60" <--- "=60"
] "+IPD,0,5:0\r\n" <--- "0\r\n"
] "+IPD,0,2:\r\n\r\n" <--- "\r\n\r\n"
] "OK\r\n" <--- "OK\r\n"
] "\r" <--- "\r"
] "\nO" <--- "\nO"
] "OK\r" <--- "K\r"
] "\nUn" <--- "\nUn"
] "Unli" <--- "li"
] "Unlin" <--- "n"
] "Unlink\r" <--- "k\r"
] "\n" <--- "\n"

[gfwilliams]

Posted at 2015-04-27 by @gfwilliams

Well, that's interesting though - Unlink is being sent, which means the connection has been closed. It should have been picked up by the driver - I'll have to look at that, because I'm sure it works on mine...

[espruino-discuss]

Posted at 2015-04-30 by DrAzzy

Figured out what's going on here.

res.on('close') is not called when the body of the response has length of 0 (which is common in REST API's), and the response never seems to get cleared out (presumably the same logic as on('close'). I have no idea how that callback is called, so I can't really pursue it further

espruino/Espruino#528

[gfwilliams]

Posted at 2015-05-01 by @gfwilliams

Ok, is that specific to the ESP8266 - did it work on CC3k/WIZnet before, or you're developing something new with the ESP8266?

Someone had similar problems with CC3000 (I think) earlier, and I'd assumed it was that the connection had closed before the connect callback got called - but it seems that may not be the case.

[espruino-discuss]

Posted at 2015-05-01 by DrAzzy

I have code running on I think v72 w/wiznet that has been making requests to that api dozens of times a day for weeks since last reset - (not certain of on('close') is being called, but I think it is... there's certainly no memory leak)

[gfwilliams]

Posted at 2015-05-01 by @gfwilliams

Strange - Just fixed it. Try this link in a few minutes: http://www.espruino.com/binaries/git/commits/5ae24206fb924569f14265fa57372132356a7a75

It could have been a regression in 1v75. I had to make sockets 'throttle' the amount they read so that data doesn't get lost when piping to something that can't take the data fast enough - that might have introduced the problem I guess.

[espruino-discuss]

Posted at 2015-05-01 by DrAzzy

Awesome, thanks! I'll give this a try tonight.

[espruino-discuss]

Posted at 2015-05-04 by DrAzzy

This looks to be working now! Hurray!