Linux Espruino - websocket send - 4 jsVars leaking each time

[espruino-discuss]

Posted at 2017-08-17 by Wilberforce

This is running on the linux version of espurino, and will apply to other boards too.

It looks like the dSnd part of the underyling socket is growing each second evert time the model is updated...

I've tried to do a simplier use case, but have not yet got a simple case working, so I'll just post what I have so far...

the output of trace() shows the dSnd string getting larger each iteration...

>trace();
#1[r2,l1] Object {
  #2[r1,l2] Name String [1 blocks] "\xFF"    #3[r1,l2] Object {
      #6[r1,l2] Name String [1 blocks] "timers"        #7[r2,l1] Array(8) [
          #382[r1,l2] Name Integer 1            #378[r1,l1] Object {
              #380[r1,l2] Name String [1 blocks] "time"= int 705003
              #381[r1,l2] Name String [1 blocks] "interval"= int 1000000
              #379[r1,l2] Name String [1 blocks] "callback"                #358[r2,l1] ...
 
            }
          #834[r1,l2] Name Integer 3            #830[r1,l1] Object {
              #819[r1,l2] Name String [1 blocks] "time"= int 693088
              #820[r1,l2] Name String [1 blocks] "interval"= int 1000000
              #803[r1,l2] Name String [1 blocks] "callback"                #890[r2,l1] Function {
                  #867[r1,l2] Name String [1 blocks] "\xFFcod"                    #1006[r1,l1] FlatString [3 blocks] "var s=JSON.stringify(model);\n    ws.send(s);\n    s=null;"
                  #779[r1,l2] Name String [1 blocks] "\xFFsco"                    #847[r2,l1] Function {
                      #781[r1,l2] Name Param "ws"                         #926[r1,l1] Object {
                          #927[r1,l2] Name String [2 blocks] "__proto__"                            #151[r4,l1] ...
 
                          #951[r1,l2] Name String [1 blocks] "socket"                            #945[r1,l1] Object {
                              #944[r1,l2] Name String [2 blocks] "__proto__"                                #394[r4,l1] ...
 
                              #863[r1,l2] Name String [1 blocks] "dSnd"                                #5[r1,l1] String [1171 blocks] "\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5373,\"counterstr\":\"01:29:34\",\"free\":3415,\"usage\":681}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5373,\"counterstr\":\"01:29:34\",\"free\":3415,\"usage\":681}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5400,\"counterstr\":\"01:29:33\",\"free\":3238,\"usage\":858}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5399,\"counterstr\":\"01:30:00\",\"free\":3234,\"usage\":862}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5398,\"counterstr\":\"01:29:59\",\"free\":3229,\"usage\":867}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5397,\"counterstr\":\"01:29:58\",\"free\":3225,\"usage\":871}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5396,\"counterstr\":\"01:29:57\",\"free\":3220,\"usage\":876}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5395,\"counterstr\":\"01:29:56\",\"free\":3216,\"usage\":880}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5394,\"counterstr\":\"01:29:55\",\"free\":3211,\"usage\":885}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5393,\"counterstr\":\"01:29:54\",\"free\":3207,\"usage\":889}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5392,\"counterstr\":\"01:29:53\",\"free\":3202,\"usage\":894}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5391,\"counterstr\":\"01:29:52\",\"free\":3198,\"usage\":898}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5390,\"counterstr\":\"01:29:51\",\"free\":3193,\"usage\":903}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5389,\"counterstr\":\"01:29:50\",\"free\":3189,\"usage\":907}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5388,\"counterstr\":\"01:29:49\",\"free\":3184,\"usage\":912}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5387,\"counterstr\":\"01:29:48\",\"free\":3180,\"usage\":916}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5386,\"counterstr\":\"01:29:47\",\"free\":3175,\"usage\":921}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5385,\"counterstr\":\"01:29:46\",\"free\":3171,\"usage\":925}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5384,\"counterstr\":\"01:29:45\",\"free\":3166,\"usage\":930}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5383,\"counterstr\":\"01:29:44\",\"free\":3162,\"usage\":934}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5382,\"counterstr\":\"01:29:43\",\"free\":3157,\"usage\":939}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"counter\":5381,\"counterstr\":\"01:29:42\",\"free\":3153,\"usage\":943}\x81j{\"setpoint\":66,\"timer\":\"90\",\"temp\":[50,50],\"countermore.. .... 

[espruino-discuss]

Posted at 2017-08-17 by Wilberforce

Here is the code (which won't run in isolation) as it requires files too...

var model = {
  setpoint : 66,
  timer : 60,
  temp: [50,50]
  //  counter : 3600
};

var event_cb = {
  timer : function (t) {
    model.counter = t * 60;
  }
};

event_cb.timer(model.timer);

function tick() {
  var d = new Date(model.counter * 1000);
  model.counterstr = d.toString().split(' ')[4];
  model.counter -= 1;
  model.free=process.memory().free;
  model.usage=process.memory().usage;

}

setInterval(tick, 1000);



function onPageRequest(req, res) {

  var a = url.parse(req.url, true);
  /**/
 // console.log(a);

  console.log({sckt:req.sckt});
  console.log(req.headers);
  //console.log(req.method);
   /**/
  var file = a.pathname;
  if (file == '/') {
    file = '/index.htm';
  }
  var headers = {};
  if (req.method == 'PUT')
    return put_file(req, res);
  var f;
  try {
    f = E.openFile('www' + file, "r");
  } catch (e) {
    // look for compressed
    try {
      f = E.openFile('www' + file + '.gz', "r");
      headers['Content-Encoding'] = 'gzip';
    } catch (e) {
      console.log('no file' + file);
    }
  }

  if (f !== undefined) {
    var mime = 'text/html';
    if (file.substr(-2) == 'js')
      mime = 'application/javascript';
    if (file.substr(-3) == 'css')
      mime = 'text/css';
    if (file.substr(-3) == 'ico')
      mime = 'image/vnd.microsoft.icon';

    headers['Content-Type'] = mime;

    res.writeHead(200, headers);
    console.log('started:' + file );
    f.pipe(res, {
      chunkSize : 512,
      end : false,
      complete : function () {
        console.log("Complete:" + file);
        f.close();
        res.end();
      }
    });

  } else {
    res.writeHead(404, {
      'Content-Type' : 'text/plain'
    });
    res.end("404: Page " + a.pathname + " not found");
  }
}

var server = require('ws').createServer(onPageRequest);

var update_model=false;

server.on("websocket", function (ws) {
  ws.on('message', function (msg) { //console.log((msg));
    var data = JSON.parse(msg);
    console.log(data);
    if ( update_model ) {
    for (var o in data) {
      //console.log( o, data[o] );
      model[o] = data[o];
      if (event_cb.hasOwnProperty(o)) {
        event_cb[o](data[o]);
      }
    }
    }
  });
  function send_model() {
    var s=JSON.stringify(model);
    ws.send(s);
    s=null;
  }
  setInterval(send_model, 1000);
});

function start() {
  server.listen(8080);
}

start();

---

Posted at 2017-08-17 by @gfwilliams

Hmm... dSnd is basically a queue - when you write to the socket, stuff gets added to it, and then when it's possible to send the data over the socket, the data from it gets sent and it's cleared.

Is this a proper 'leak' - as in - you type quit() and then leaked variables are reported? Or it's just that dSnd keeps growing? If it's growing I'd assume it is because for whatever reason the socket hasn't been able to send the data? Maybe it's closed? That could be a bit of a bug I guess - if it's closed it should error if you try and write to it.

---

Posted at 2017-08-17 by Wilberforce

Thanks for the reply..

In chrome on the receiving end of the web socket, I can see the json packets coming in 106 bytes at a time, so they are getting sent once... so I wonder if this is a bug related to the fact that the websocket does not close, so the current data gets added to the queue, the most recent addition gets sent, but because the socket is not closed, the queue keeps on growing. Probably not explained myself very well!

I'll have to try the quit() tomorrow..

---

Posted at 2017-08-17 by @gfwilliams

It's possible, yes... So there's no data being taken off the beginning of dSnd even though it's being sent?

---

Posted at 2017-08-17 by @gfwilliams

I just tried this:

var page = '<html><body><script>var ws;setTimeout(function(){';
page += 'ws = new WebSocket("ws://" + location.host + "/my_websocket", "protocolOne");';
page += 'ws.onmessage = function (event) { console.log("MSG:"+event.data); };';
page += 'setTimeout(function() { ws.send("Hello to Espruino!"); }, 2000);';
page += '},2000);</script></body></html>';
var onPageRequest = function(req, res) {
  res.writeHead(200, {'Content-Type': 'text/html'});
  res.end(page);
};
var server = require('ws').createServer(onPageRequest);
server.listen(8000);
server.on("websocket", function(ws) {
  var count = 0;
  console.log("Connection upgraded");
  ws.on('message',function(msg) {
    console.log("Message received");
    print("[WS] "+JSON.stringify(msg));
  });
  ws.on('close',function(msg) {
    if (intr) clearInterval(intr);
  });
  var intr = setInterval(function() {
    ws.send("Hello "+count++);
  }, 1000);
});

and it works fine - I don't see any leak at all.

However, when I remove ws.on('close' and close the connection then it starts to leak memory.

So yeah, that's it. I reckon the connection is actually closing properly, we're just accepting writes on a closed connection when we should be erroring.

I filed an issue: espruino/Espruino#1220

---

Posted at 2017-08-17 by @gfwilliams

Fixed now. Your code will error after that, and you just need to clear the send_model interval on ws.on('close'.

---

Posted at 2017-08-17 by Wilberforce

@gfwilliams
Thanks very much Gordon for your help!

I have added the ws.on('close') and confirmed it works, and also rebuilt with your fix and confirmed that throws an error too!

When you mentioned quit() above - that does not work in the left side of ide - where do you use this?

---

Posted at 2017-08-18 by @gfwilliams

It's a linux-only thing. Basically it quits 'nicely', and then runs a quick check for leaked memory afterwards :)