random INVALID_STATE_ERR errors thrown causing program to crash

[alaa-eddine]

Hello,
I'm using sockjs for a multiplayer game server, and I'm getting random INVALID_STATE_ERR errors.
I didn't find a test case that reproduce it, seems just to happen randomly.

the problem is that this error is thrown, and I don't know how or where to catch it to prevent server from crashing .

what can cause this error ? and how to catch it ?

[majek]

Do you see this error in node.js caused by sockjs-node or in browser caused by sockjs-client?

[alaa-eddine]

no I see it in server side sockjs-node here is the trace :

somepath/node_modules/sockjs/lib/transport.js:195
        throw Error('INVALID_STATE_ERR');
              ^
Error: INVALID_STATE_ERR
    at Error (unknown source)
    at Session.didTimeout (somepath/node_modules/eureca/node_modules/sockjs/lib/transport.js:195:15)
    at XhrPollingReceiver.GenericReceiver.didAbort (somepath/node_modules/sockjs/lib/transport.js:285:35)
    at Socket.GenericReceiver.setUp.thingy_end_cb (somepath/node_modules/sockjs/lib/transport.js:269:22)
    at Socket.EventEmitter.emit (events.js:90:17)
    at TCP.onread (net.js:417:51)

[majek]

This is curious. See this:
https://github.com/sockjs/sockjs-node/blob/master/src/transport.coffee#L165

There are exactly two possibilities: a) @ReadyState is CONNECTING b) it is CLOSED. Both are equally weird. Can you print "@ReadyState" with the error, to figure out which one of those cases occurs?

Plus, I need to know which transport is used.. Your traceback suggests XhrPolling.

[alaa-eddine]

I'll add logs to see print readyState and wait for the error to occure (as I said I didn't find a way to reproduce it)

we can eliminate the a possibility because there are allways connected players before (this mean that readystate != CONNECTING right ? )

is it possible that this happens with fallback protocoles while XHR polling for example ?

[majek]

As an emergency measure, if the readyState is equal to CLOSED, you can just 'return' instead of throwing error there. That should work.

Still, I'd like to find a root cause of that. What node are you using btw? Also, are you behind haproxy?

[alaa-eddine]

I added some debug messages to get more information I'll comment back when it happens again.

[alaa-eddine]

Got it ! I reproduced the bug.
it hapens when xhr streaming is used instead of websocket ... when the xhr poll timeout without sending or receiving anything (in the client side) it cause the server to throw an invalid state with readystate=3

If the client make an action before xhr timeout a new xhr request is made and the problem does not occure.

[alaa-eddine]

humm after re-reading my comment I'm not sure if it's the client timeout who is causing the server error state or the server error state who is causing the client connection to abort :/

[majek]

Again, are you behind haproxy? Or on heroku maybe?

[alaa-eddine]

I'm behind a varnish proxy... is it a know issue with proxies ?

[majek]

No, this traceback is just triggered by network event (TCP.onread in your traceback), so I'd like to know exactly what is your network setup. Which nodejs version?

[alaa-eddine]

I'm using nodejs v0.8.11
I installed a varnish proxy to cache static content and because it have a native support for websockets.
the configuration is quite simple, varnish listen on port 80 and forward requests to port 8000 where my nodejs server is listening.

[majek]

I must say I have no clue how this traceback can be triggered. Are you running sockjs-node from npm (if so, what version?), or did you build it manually from dev branch?

Aren't you doing something stupid in your code, like manually setting readyState to CLOSED? Or hardcoding session_id?

You said you know how to reproduce this traceback, can you explain this in detail?

[alaa-eddine]

I'm using latest sockjs npm version. and I'm not overriding readyState.

but when a client log in, he is authentified (using passport module), but hen I need to authenticate sockjs connection, so the client will send a token as a first message, this token is stored in session_id, is this wrong ?

do I need to store this token in another field ?

the reproduction behaviour is not working I was wrong, but I'm pretty sure it only hapens with fallback protocols, when client support websocket the problem never occure (from my logs).

[majek]

this token is stored in session_id

Can you elaborate? Can you paste few lines of code that relate to this?

but I'm pretty sure it only hapens with fallback protocols,

SockJS doesn't really do fallbacks. It establishes a new session every time it tries a new protocol. So from server side the session number is unique and is attached to exactly one transport.

[alaa-eddine]

here is the exact scenario + relevant source code I'm using .
a client authentifies itself using passport-connect, then he start a game, before the game start sockjs need to be authentified, the client send the sid stored in connect.sid cookie, that sid is used to deserialise connect user.

here is the code called for authentication.

auth.sockjsAuth = function(avatarId, conn, sid, callback) {

    var _this=this;

    auth.sessionStore.get(sid, function (err, session) {

        if (session === undefined) //No session ?
        {
            Logger.log('sockjs auth failed');
            conn.close(401, 'Authentication failed');
            return;
        }

        this.passport.deserializeUser(session.passport.user, function (err, user) {

            if (user === undefined) {
                Logger.log('sockjs auth failed');
                conn.close(401, 'Authentication failed');
                return;
            }

            //Handle anonymous connection
            if (user && user.anonymous) 
            {
                Logger.log('Authenticated ', user.id, sid);
                conn._session.session_id = sid;
                conn._session.userid = user.id;

                if (typeof callback == 'function') callback();
                return;
            }



            //Handle authenticated connection
            dal.findAvatar(avatarId, user.id, function (err, avatar) {
                if (err) {
                    Logger.log('Authentication error while validating avatarId', err);
                    conn.close(401, 'Authentication failed');
                    return;
                }       
                if (avatar)
                {
                    conn._session.session_id = sid;
                    conn._session.userid = user.id;
                    if (typeof callback == 'function') callback();
                }
            });             
            return;
        });


    });

}

to get a better idea of what I'm doing you can check the online demo using this code here : http://demo.ezelia.com/
once connected (using anonymous login), pick an avatar, the game will start, there are some general debug messages in the browser console, but I don't think they are relevant for this issue.

[majek]

Okay, this line is very wrong and is causing this traceback.

                conn._session.session_id = sid;

I'm actually surprised that sockjs-node continues to work at all. Do not touch _session object please.

[alaa-eddine]

ok I'll modify the code to store the sid in another field.
I thought this was the good way to do since session_id seemed to me to be allways empty. so I thought I should put a unique id there to maintain the session.

thank you for your help :)

btw, I'm using sockjs to write a RMI library (like nowjs) : https://github.com/alaa-eddine/eureca

[majek]

Ok, please let me know if modified code works.

[alaa-eddine]

is it ok if I store all my custom values in a subobject ?

conn._session._myobj.sid = sid
conn._session._myobj.userId = id