Issue with caching session data?

[adammockor]

Hello, since update 1.0.6, I am experiencing issue that, session isn't correctly populated with data from MongoDB. After auth process user is correctly saved to session store in db, but next request gets data from cache where user data are not present.

Maybe the problem is somewhere else, I am not sure, but everything works as expected, when I set version back to 1.0.5 or set express-session to default store.

My express middleware flow is this:

app.use(cookieParser(process.env.SESSION_SECRET));
app.use(session({
  secret: process.env.SESSION_SECRET,
  store: new MongoStore({
    db: mongoose.connection.db,
    ttl: 86400000
  }, function(err) {
    log.error(err);
  }),
  cookie: {
    expires: new Date(Date.now() + 86400000),
    maxAge: 86400000
  },
  resave: true,
  saveUninitialized: true
}));

passport.serializeUser(function (user, done) {
  done(null, user);
});

passport.deserializeUser(function (obj, done) {
  done(null, obj);
});

app.use(passport.initialize());
app.use(passport.session());

package.json

"express": "~4.14.0",
"express-mongoose-store": "1.0.6",
"express-session": "~1.14.2",
"passport": "^0.3.0",

[battlejj]

@adammockor I'll take a look into this today, looks like we need better test coverage because this is something that should've been caught before the PR came in.

Just to make sure I understand the issue, let me know if this sounds accurate: you are saying after successful authentication the users session is persisted MongoDB but it isn't propagated to the cache. This causes an issue because the next request checks the cache and a cache miss occurs. The library does not go back to MongoDB for the session data. Is this right?

[adammockor]

Right, but there is never a cache miss. There is always data in cache.get, because I am creating session cookie for first request even for not-logged 'users' (so every request has a session).

[battlejj]

Oh okay, so the issue is really that the cache isn't updating when there is fresh data in Mongo? You are just seeing the initial cached session from before authentication?

[adammockor]

Maybe some kind of async problem? Here is debug. I added url routes and replaced session data with [MY_DATA]

Route: /auth
mongoose-store GET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +0ms
mongoose-store Setting cache and returning valid session. +4ms
mongoose-store SET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +6ms
mongoose-store Session record is: {"session":"{\"cookie\":{\"originalMaxAge\":86400000,\"expires\":\"2017-01-22T18:20:12.266Z\",\"httpOnly\":true,\"path\":\"/\"},\"passport\":{}}","created":1485022812266} +0ms
mongoose-store Session updated. +6ms
mongoose-store Try to JSON parse {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:19:58.999Z","httpOnly":true,"path":"/"},"passport":{}} +0ms
mongoose-store Set cache and return the session {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:19:58.999Z","httpOnly":true,"path":"/"},"passport":{}} +0ms

Route: /auth/callback
mongoose-store GET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +591ms
mongoose-store Returning session from cache +1ms
mongoose-store SET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +10s
mongoose-store Session record is: {"session":"{\"cookie\":{\"originalMaxAge\":86400000,\"expires\":\"2017-01-22T18:20:22.616Z\",\"httpOnly\":true,\"path\":\"/\"},\"passport\":[MY_DATA],"created":1485022822616} +0ms
mongoose-store Session updated. +5ms
mongoose-store Try to JSON parse {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:20:12.266Z","httpOnly":true,"path":"/"},"passport":{}} +0ms
mongoose-store Set cache and return the session {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:20:12.266Z","httpOnly":true,"path":"/"},"passport":{}} +0ms

Route: /app (redirect after successful auth)
mongoose-store GET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +12ms
mongoose-store Returning session from cache +0ms
mongoose-store SET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +2ms
mongoose-store Session record is: {"session":"{\"cookie\":{\"originalMaxAge\":86400000,\"expires\":\"2017-01-22T18:20:22.635Z\",\"httpOnly\":true,\"path\":\"/\"},\"passport\":{}}","created":1485022822635} +0ms
mongoose-store Session updated. +3ms
mongoose-store Try to JSON parse {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:20:22.616Z","httpOnly":true,"path":"/"},"passport":[MY_DATA]} +0ms
mongoose-store Set cache and return the session {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:20:22.616Z","httpOnly":true,"path":"/"},"passport":[MY_DATA] +0ms

Route: /login (redirect after isAuthorized === false)
mongoose-store GET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +12ms
mongoose-store Returning session from cache +0ms
mongoose-store SET 6yp7AibgHhW5KJy1jKZ7k_fOKYfTgDqg +408ms
mongoose-store Session record is: {"session":"{\"cookie\":{\"originalMaxAge\":86400000,\"expires\":\"2017-01-22T18:20:23.058Z\",\"httpOnly\":true,\"path\":\"/\"},\"passport\":[MY_DATA],"created":1485022823058} +0ms
mongoose-store Session updated. +2ms
mongoose-store Try to JSON parse {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:20:22.635Z","httpOnly":true,"path":"/"},"passport":{}} +0ms
mongoose-store Set cache and return the session {"cookie":{"originalMaxAge":86400000,"expires":"2017-01-22T18:20:22.635Z","httpOnly":true,"path":"/"},"passport":{}} +1ms

[battlejj]

Did a bit of a rewrite today, still working on the testing of the new code. Any chance you could create a really simple example I could use to reproduce this result? If it's too much work I understand, I'll do my best to replicate on my own but figured I'd ask.

[adammockor]

I was trying to replicate it as close as possible, but here it is working as it should :(. Here is gist of my code.

BTW in real app I am using passport-asana instead of fake auth in my gist.

And no pressure, I can live with older version perfectly. Thank you for your work and time!