Socket.io 1.2.1 + nodejs 0.10.32 error 324 ERR_EMPTY_RESPONSE

[flashmandv]

I'm using nodejs version 0.10.32 and Socket.IO 1.2.1 to build app. When the server is working for couple of hours, at some point it stops accepnting connections and returns error 324 ERR_EMPTY_RESPONSE. The strange thing is that it does not completely stops, but it stops in most cases. After the 5-10th connection attempt - it succees.

The url that my flash client is loading is this:
http://HOST:PORT/socket.io/?EIO=2&time=1419436839425&transport=polling

I opened another case for socket.io 0.9 version (#1913), but after upgrading - the problem still exists :(
Please help

[nkzawa]

We need more information of the error. Where does the error happen, server or client? What do you use for your flash client? Could you post dump of logs?

[flashmandv]

It happens on the server after about 10 hours of work. The more players are connected - the more often it happens. In normal cases the flash client receives status code 200 and data, but when the server hangs - it starts receiving the 324 error on discover process and after about 5-10 reconnects - it connects again.
I'm not sure how to enable detailed server log of process of connecting ?
The flash client I'm using is this one:
https://github.com/redannick/FlashSocket.IO/tree/1.0.x

[nkzawa]

How to enable debug logs: DEBUG=* node server.js

http://socket.io/docs/logging-and-debugging

I wonder whether it's the problem of socket.io because we have never heard of the issue before with the js client.

[flashmandv]

It must be server problem (socket.io or node.js) because the problem happens also with the .js client (I setup test js client which also throw the same 324 ERR_EMPTY_RESPONSE error and also the browser displays it when I try to open the URL myself.

[flashmandv]

Right now the problem exists..I'll restart the server in 5 minutes but the logs were enabled and this is what they said (not sure it is the one because there are many clients connected right now):

20:46:30 GMT socket.io:client client close with reason ping timeout
20:46:30 GMT socket.io:socket closing socket - reason ping timeout
20:46:30 GMT socket.io:client ignoring remove for x2Yq0AGRrXWz6ywPATZj

I tried to connect now with the JS client and it received this:
socket.io-client:url parse http://boardgamesonline.net:16002 +0ms
socket.io-1.2.1.js:1 socket.io-client new io instance for http://boardgamesonline.net:16002 +0ms
socket.io-1.2.1.js:1 socket.io-client:manager readyState closed +0ms
socket.io-1.2.1.js:1 socket.io-client:manager opening http://boardgamesonline.net:16002 +0ms
socket.io-1.2.1.js:2 engine.io-client:socket creating transport "polling" +0ms
socket.io-1.2.1.js:2 engine.io-client:polling polling +2ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr poll +2ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr open GET: http://boardgamesonline.net:16002/socket.io/?EIO=3&transport=polling&t=1419546055127-0 +1ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr data null +1ms
socket.io-1.2.1.js:2 engine.io-client:socket setting transport polling +1ms
socket.io-1.2.1.js:1 socket.io-client:manager connect attempt will timeout after 20000 +8ms
socket.io-1.2.1.js:1 socket.io-client:manager readyState opening +1ms
socket.io-1.2.1.js:2 engine.io-client:polling polling got data ArrayBuffer +74ms
socket.io-1.2.1.js:2 engine.io-client:socket socket receive: type "open", data "{"sid":"kh7gLn7S7sV41AfzAXw2","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":60000}" +4ms
socket.io-1.2.1.js:2 engine.io-client:socket socket open +0ms
socket.io-1.2.1.js:1 socket.io-client:manager open +78ms
socket.io-1.2.1.js:1 socket.io-client:socket transport is open - connecting +0ms
socket.io-1.2.1.js:2 engine.io-client:socket starting upgrade probes +3ms
socket.io-1.2.1.js:2 engine.io-client:socket probing transport "websocket" +1ms
socket.io-1.2.1.js:2 engine.io-client:socket creating transport "websocket" +1ms
socket.io-1.2.1.js:2 engine.io-client:polling polling +2ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr poll +1ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr open GET: http://boardgamesonline.net:16002/socket.io/?EIO=3&transport=polling&t=1419546055216-1&sid=kh7gLn7S7sV41AfzAXw2 +1ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr data null +0ms
socket.io-1.2.1.js:3 WebSocket connection to 'ws://boardgamesonline.net:16002/socket.io/?EIO=3&transport=websocket&sid=kh7gLn7S7sV41AfzAXw2' failed: Connection closed before receiving a handshake response
socket.io-1.2.1.js:2 engine.io-client:socket probe transport "websocket" failed because of error: Error: websocket error +24ms
socket.io-1.2.1.js:2 engine.io-client:polling polling got data ArrayBuffer +10ms
socket.io-1.2.1.js:2 engine.io-client:socket socket receive: type "message", data "0" +0ms
socket.io-1.2.1.js:1 socket.io-parser decoded 0 as %j +0ms Object
socket.html:5 on connect
socket.io-1.2.1.js:2 engine.io-client:polling polling +0ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr poll +0ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr open GET: http://boardgamesonline.net:16002/socket.io/?EIO=3&transport=polling&t=1419546055251-2&sid=kh7gLn7S7sV41AfzAXw2 +0ms
socket.io-1.2.1.js:2 engine.io-client:polling-xhr xhr data null +0ms

This was my test code:

<script src="https://cdn.socket.io/socket.io-1.2.1.js"></script> <script> var socket = io('http://boardgamesonline.net:16002'); socket.on('connect', function(){console.log('on connect')}); socket.on('event', function(data){console.log('event:',data)}); socket.on('error', function(data){console.log('err:',data)}); socket.on('disconnect', function(){console.log('on disconnect')}); </script>

I really don't know what to do now :(

[nkzawa]

Thanks for the logs, but where is the error? If the error is shown only in client, can I see it too?

[flashmandv]

The client error itself was something like:
GET http://boardgamesonline.net:16002/socket.io/?EIO=3&transport=polling&t=1419546055216-1 net::ERR_EMPTY_RESPONSE

The error is also shown in the browser when you try to open the URL.
Now it works and if you open it with chrome for example - it will download some response file with SID ..
But when the server hangs - it will give the 324 error above (in ~90% of the attempts)
I'm also trying nodetime to investigate the problem and it shows in OS/Total Memory peak at the problematic time - which is in range 20000000000000 MB

[nkzawa]

It looks net::ERR_EMPTY_RESPONSE happens when the server doesn't send any response.
I could reproduce the error by closing underlying tcp socket before sending any data like the following.

req.socket.end();

I'm not sure yet but I guess this is because the server is too busy.

[flashmandv]

I'm not calling the .end() function anywhere.
My main code looks like this:

var io = require("socket.io")({'heartbeat interval':15, 'heartbeat timeout':40});
socket = io.listen(port, {logger : {
debug: winston.debug,
info: winston.info,
error: winston.error,
warn: winston.warn
}});

socket.sockets.on("connection", onSocketConnection);
socket.sockets.on("error", onError);

var onSocketConnection = function(client) {
//console.log("New player has connected: "+client.id);
client.on("disconnect", onClientDisconnect);
client.on("error", onError);
.....
};

Any idea how can I debug the memory issue and see if there is a memory leak or something that can affect the socket.io ?
Btw the problems will happen in the next hour probly. You can see the problem (if I did not restarted the server) by opening:
http://boardgamesonline.net/socket.html

[flashmandv]

It turns out the problem is caused by memory leak.
I removed most of my app code and made flame map
http://bgdevs.com/out.nodestacks05.svg

It looks like the socket.io is leaking. Is this normal ?
nodejs 0.11.14 + socket.io 1.2.1

[flashmandv]

It turned out to be memory leak in the winston 0.8.0 package.

[flashmandv]

It seems the problem happens again. It is not the memory leak that is causing it.
I fixed the memory leak and now after the system is not loaded at all - it happens again.
It seems socket.io can handle only small load of maximum 200 connections, but definitely not thousands...