Recover a session manually when req.session is undefined

[tciuro]

Hello,

Consider the snippet as shown in the documentation:

app.use(session( /* setup session here */ ))
app.use(function (req, res, next) {
  if (!req.session) {
    return next(new Error('oh no')) // handle error
  }
  next() // otherwise continue
})

When req.session is not available, I ping Redis and it's available. The problem is that the request has already gone through the middleware. Would it be possible to include a function call in connect-redis to allow reloading the session manually? In other words, tell connect-redid to "try again". If we could obtain a session then, we could salvage the situation.

[tciuro]

The problem is that once I get in this state, connect-redis never recovers. I get a !req.session on every single request... but Redis is working fine (I can access it without problems from terminal). Other than restarting the server (which sucks), is there a way to re-initialize connect-redis so that the next request can be properly initialized with a session?

[tciuro]

I forgot to mention that we're using 1.4.7.

[wavded]

Something like this should really be handled upstream in the express-session project as we'd want a common API for any session store. I don't mind the idea though. Care to put up an issue there?

https://github.com/expressjs/session

[tciuro]

Sure thing:

expressjs/session#99

Thanks Marc!

[dougwilson]

The issue belongs here. Why can't the store retry on failures?

[dougwilson]

In addition, the following seems like an issue with this module:

The problem is that once I get in this state, connect-redis never recovers. [...] Other than restarting the server (which sucks), is there a way to re-initialize connect-redis so that the next request can be properly initialized with a session?

Why would connect-redis not recover? The interface between the session manager and the store is to just send you all lookup requests unless you tell us not to by (by way of the disconnect event). We'll start sending then again when you tell us to (by way of the connect event).

[wavded]

@dougwilson

@tciuro this sounds like an issue with node_redis, it should attempt to reconnect indefinitely, we don't manage any reconnects in this library.

[wavded]

agr... submitted early somehow, let's try this again

@dougwilson the question of re-running the session though the middleware (the example you gave in the express-session project) is the sort of functionality I was getting at in my comment... or are you expecting libraries to continually retry and/or provide retry configuration until they get a session before going to the next middleware? Retry behavior seems something global to any network/disk session stores.

[dougwilson]

or are you expecting libraries to continually retry and/or provide retry configuration until they get a session before going to the next middleware?

right, that is our opinion. When we call the store to fetch a session, we only assume a reliable connection. Stores that do not have a reliable connection would be responsible for retrying, mainly because we have no way to know when to retry or when your session didn't exist, or when you had a fatal error and we shouldn't even bother retrying.

[wavded]

@dougwilson thanks, that perspective is helpful, I'll take a peak and implement some sort of continual retry. This retry logic would be opt-in at this point as it may be breaking for some people but perhaps can be made default in a future release.

[tciuro]

@wavded + @dougwilson

For what is worth, the issue is only reproducible when using Node's cluster API. When I run it in single-process, I don't see a single mention of the session not being loaded (the message is being displayed via my code, when I detect `req.session === undefined'.

The moment I run it with clustering on (one node per core), all hell breaks loose.

[tciuro]

@wavded

We introduced a leak in our app. Once our server is under heavy load, we decide to shoot/relaunch the offending cluster worker that starts to misbehave. It's temporary until we find the culprit, but for now we keep this in place to allow the server to continue working. Each time a cluster worker bounces back, it gets inited with the same exact code path, where the session object is configured, a new RedisStore is allocated and assigned to the session, etc. Could it be that this worker management strategy is introducing an issue in connect-redis? (or even node_redis) Perhaps connect-redis is left in a state where it doesn't know or cannot reconnect? Just wondering... :-/

I'm going to try something else: run the app in cluster mode without the worker management strategy activated. Let's see this issue appears again. I'll report back ASAP.

[wavded]

Thanks for the update @tciuro (wish it was under better circumstances). What kind of logs to you get if you create a Redis client first and listen for its 'error' events? Anything telling?

var client = require('redis').createClient(...)
client.on('error', console.log)
...
app.use(session({ store: new RedisStore({ client: client }) ... }))

[tciuro]

@wavded

Glad to try getting to the bottom of this! :-)

Just as I suspected, killing the cluster worker has negative implications. If I enable clustering but disable the "cycle worker" strategy, I never see this issue (though of course, the app starts leaking without an end in sight, other than bringing down the server).

I've added the client.on('error', console.log) to see what gets displayed. I'll report back ASAP.

[tciuro]

@wavded

I have added support for the following Redis client events: ready, connect, error, end and drain. During a full hour run, I only see the ready, connect and drain events. I never see error or end mentioned anywhere in the log. So it doesn't look like Redis ever spews an error or gets disconnected.

[tciuro]

@wavded

A little more info. I have done two things: 1) add more logging in my app and 2) add more logging in connect-redis, where I display the client event before emitting. I also have launched my app using the DEBUG=connect:redis flag.

This is what I see right before the first failure: the user has been authenticated, the session saved and the request returned successfully. The next request comes in and boom! The session cannot be retrieved. No error or event whatsoever has been displayed after the login succeeded and the session got saved:

info [2014-11-21 12:58:08.445][FA2DD:86CC6:6]        [Auth - parseBasicAuthHeaderAndAuthenticate] user "admin" authenticated successfully.
  connect:redis SETEX "session:acwkQYZ9WfRAszHVpoZZGn8k" ttl:86399 {"cookie":{"originalMaxAge":86400000,"expires":"2014-11-22T20:58:08.311Z","secure":true,"httpOnly":true,"path":"/"},"username":"admin"} +103ms
  connect:redis SETEX complete +0ms
info [2014-11-21 12:58:08.445][FA2DD:86CC6:6]    [Auth - login] authentication successful.
  connect:redis SETEX "session:acwkQYZ9WfRAszHVpoZZGn8k" ttl:86400 {"cookie":{"originalMaxAge":86400000,"expires":"2014-11-22T20:58:08.445Z","secure":true,"httpOnly":true,"path":"/"},"username":"admin"} +0ms
  connect:redis SETEX complete +1ms
POST /api/auth/login 204 105ms
warn [2014-11-21 12:58:08.496][App - start] session not loaded! Pinging Redis...
warn [2014-11-21 12:58:08.496][App - start] Session was not loaded even though Redis is available. Going to attempt reloading it manually...
warn [2014-11-21 12:58:08.497][App - start] Attempting to load the session: 1 of 3...
warn [2014-11-21 12:58:08.497][App - start] Attempting to load the session: 2 of 3...
warn [2014-11-21 12:58:08.497][App - start] Attempting to load the session: 3 of 3...
error [2014-11-21 12:58:08.497][App - start] Session could not be loaded even though Redis is available. Please try again later.

Then, a new request comes along, only this time...:

warn [2014-11-21 12:58:08.614][App - start] session not loaded! Pinging Redis...
warn [2014-11-21 12:58:08.614][App - start] Session was not loaded even though Redis is available. Going to attempt reloading it manually...
warn [2014-11-21 12:58:08.614][App - start] Attempting to load the session: 1 of 3...
  connect:redis GET "session:acwkQYZ9WfRAszHVpoZZGn8k" +3s
  connect:redis GOT {"cookie":{"originalMaxAge":86400000,"expires":"2014-11-22T20:58:08.445Z","secure":true,"httpOnly":true,"path":"/"},"username":"admin"} +0ms

Bingo! The last request was lucky enough to obtain the session after two tries (the original one + the retry). Weird, no? Any hunch about what could be causing this?

[dougwilson]

@tciuro just out of curiosity, can you add a log within the function at https://github.com/tj/connect-redis/blob/master/lib/connect-redis.js#L115 and see if that gets called? Just add a log before the .emit.

[tciuro]

@dougwilson

That is precisely what I did already. See step 2 in my previous comment (i.e. add more logging in connect-redis, where I display the client event before emitting). When the issue occurs, the log statement I just added doesn't log anything. The same as if I listen to the event directly in my app. It doesn't look like Redis is erring.

[dougwilson]

That is precisely what I did already. See step 2 in my previous comment

I know, but you said you just added event listeners. I just wanted to add extra verification by adding a log directly within that anonymous function.

[tciuro]

OK, no worries. We're on the same page :-)

[wavded]

@tciuro, you are on 1.4.7 because of express 3 right?

We really should be supporting express 3 and 4 in the latest releases and it doesn't seem like it should be hard to do. That would allow you to use the latest redis (which may have addressed this issue). Unfortunately, the redis project changed their API in a way that will break 1.4.7 if its updated.

I've been playing around with retry and it looks more complicated than it should be, hopefully a solution will arise. redis automatically caches commands that couldn't complete and then reissues them after a connection is (re)established, but this isn't consistent all the time, there are cases when that cache is cleared. It also calls back on an error but also caches... so I'm a little confused on how to do the right thing. Preferably, this would be solved in redis land but...

[tciuro]

@wavded

Correct, I'm using 1.4.7 as per doc. I'd love to migrate everything to the latest version, but as you know, it's not that easy once it's in production. Still though, Express 4 is something I definitely want to move towards ASAP.

I'll start updating the code by using express-session first and hopefully stabilize the app.

[tciuro]

Well, I have been testing on two Macs and so far I haven't seen the issue! I'm going to continue testing for the next couple days to see whether the issue has been truly solved. The middleware that I added thanks to @dougwilson still attempts to obtain the session, retrying a couple times and always succeeding. This is why I'm not yet 100% sure that the issue has been solved, but things do look way, way better.

[dougwilson]

Good to hear :) Here's to not jinx it :) Feel free to update me on anything. I'm glad I asked what version of Express you were even on :)

[tciuro]

@wavded, @dougwilson

I learned that the updating frequently minimizes the amount of incompatibilities one can find. Because it's been so stable until now, we haven't had the need to bring anything up to date. Until now, that is. So thanks for the patience and guidance.

One question: is there a reason why the built-in version of redis in connect-redis is still 0.10.3? The latest version of redis is 0.12.1.

[wavded]

That's because the redis API changed, and we never updated the Express 3 version of connect-redis, the new versions (that work with Express 4) are up to date.

[tciuro]

Is there a problem if I use redis 0.12.1 directly with Express 3.4.8 that you're aware of? After 2 days testing I haven't had an issue with it so far on three different Macs. Are you planning to bring connect-redis for Express 3 up to date? Just wondering...

[dougwilson]

The real question, I think, is what makes it not compatible with Express 3? Can @tciuro use the latest express-session with Express 3 (which he is and it's compatible) and also use the latest connect-redis with it as well?

[wavded]

here is the issue for reference: #110. if @tciuro can use the latest express-session with Express 3, than connect-redis latest will be compatible. If that's all it takes, maybe I should update the readme for Express 3 users?

[dougwilson]

If that's all it takes, maybe I should update the readme for Express 3 users?

Yea. In fact, the latest Express 3 uses the latest express-session under the hood of express.session. The biggest difference is 0.8 vs 0.10, which is there the support differs.

[tciuro]

@wavded + @dougwilson

I have been running 70+ integrations using Xcode Server on two different Macs since Saturday. I have yet to see the issue appear. I think the problem went away "simply" by upgrading (though it really wasn't just a drop-in replacement; I had to remove a series of deprecated calls as well as updating the middleware with the newer API). I would like to thank you both for the awesome help you've provided. I really appreciate it very much.

@wavded, perhaps it would be a good idea to update the ReadMe for Express 3 users. I'd like to upgrade to Express 4 ASAP, but for other people not having the opportunity, it'd be great to have this sort of information. Again, thanks for everything.

[wavded]

I went ahead and updated the readme. Good discussion.