Race condition: `store.get()` called before `session.save()` is complete

[jamesplease]

Sometimes, when a user signs into my app, they are registered as not being logged in. I've narrowed it down to what seems to be a race condition in this library.

The tl;dr is that the .save() function is called from the index.js file of this library, initiating the process of saving the session to the DB. However, the middleware continues on its way, calling .get() before the session has saved. Therefore, it doesn't find the session, and doesn't set it to req.session.

This leads Passport downstream to think that the user isn't authenticated. When the user refreshes, typically the save has finished at that time, and they are now logged in.

Has anyone encountered this before?

I'm using this with Passport and simple-pg-connect for persisting the session to the DB, but every other piece to the puzzle seems to be working correctly except for this one (at least, from what I can gather).

The project that this is going in is open source. The middleware is being configured here:

https://github.com/jmeas/finance-app/blob/google-sign-in/server/app.js

and the Passport configuration can be seen here:

https://github.com/jmeas/finance-app/blob/google-sign-in/server/utils/configure-passport.js

[dougwilson]

If you are doing a redirect on the login process, that can cause this in certain web browsers that perform the redirect before they even finish receiving the response. You can see if this is the case for you be not calling res.redirect until after the session has saved in your login routine. Example:

req.session.save(function () { res.redirect(...); });

[jamesplease]

Thanks for the suggestion, @dougwilson . So far, it doesn't look like there's any way for me to intercept this behavior; it all seems to happen in a few lines of code inside of this library's main function.

My thought that it's an internal race condition caused by an async save was further backed up by wrapping this call to get in a setTimeout. By giving it a moment to wait for the save to succeed, it was able to retrieve the correct session data, and everything worked as expected.

I'm experiencing very similar behavior on logout (the first logout doesn't work sometimes), and I'm beginning to suspect it's another race condition, where it's retrieving the old session before the deletion has completed.

I'm still trying to wrap my head around this code, but at first glance it doesn't seem very async friendly. The call to save seems to be made separately from get in the same middleware function...how can there be any guarantee that it will have completed when the call to get is made?

Here's the log of relevant events in the flow. At the start of the log, there are 0 sessions in the database.

# The user has clicked login on the Google page, and are redirected
12:02:28 AM web.1 |  -----New request /auth/google/callback
# the `logIn` method from Passport is being called, which
# means we've received a Google profile
12:02:29 AM web.1 |  logging in!
# the `serialize` method from Passport is being called, which
# is what turns a Google profile into the object we want to
# persist to the session
12:02:29 AM web.1 |  serializing
# Now that we have our serialized user, this is the call from 
# `express-session` that begins the query to save the session
12:02:29 AM web.1 |  sessionIndex: about 2 save
# connect-pg-simple receives the request to save the
# session; it starts doing that
12:02:29 AM web.1 |  pgSimple: setting tCznnEIuDbiwHSWVYXhbmJR-OFDLBcSR
# express-session is now making a request to retrieve the 
# session that is currently being saved
12:02:29 AM web.1 |  fetching session tCznnEIuDbiwHSWVYXhbmJR-OFDLBcSR
# connect-pg-simple receives the request to get the session; it starts doing that
12:02:29 AM web.1 |  pgSimple: getting tCznnEIuDbiwHSWVYXhbmJR-OFDLBcSR
# connect-pg-simple has completed the fetch query
12:02:29 AM web.1 |  query happened
# connect-pg-simple reports that it found nothing
12:02:29 AM web.1 |  no session found
# because the Google callback was successful, Passport redirects me to success
12:02:29 AM web.1 |  -----New request /success
# however, the fetch failed, and no session data was loaded. Therefore,
# Passport reports that I'm unauthenticated
12:02:29 AM web.1 |  authenticated: false
# finally, things end with connect-pg-simple announcing that it's about
# to create the session
12:02:29 AM web.1 |  pgSimple: creating
# and shortly after it finishes doing that
12:02:29 AM web.1 |  sessionIndex: save complete

[jamesplease]

Thanks for the suggestion, @dougwilson ! I'll have to dig into the Passport internals to see if I can modify the redirect behavior.

In the meantime, I've debugged this a bit further. Here's a log of events:

# The user has clicked login on the Google page, and are redirected
12:02:28 AM web.1 |  -----New request /auth/google/callback
# the `logIn` method from Passport is being called
12:02:29 AM web.1 |  logging in!
# the `serialize` method from Passport is being called
12:02:29 AM web.1 |  serializing
# This is the call from `express-session` that begins the query to save the session
12:02:29 AM web.1 |  sessionIndex: about 2 save
# connect-pg-simple receives the request to save the session; it starts doing that
12:02:29 AM web.1 |  pgSimple: setting tCznnEIuDbiwHSWVYXhbmJR-OFDLBcSR
# express-session is now making a request to retrieve the session that is currently being saved
12:02:29 AM web.1 |  fetching session tCznnEIuDbiwHSWVYXhbmJR-OFDLBcSR
# connect-pg-simple receives the request to get the session; it starts doing that
12:02:29 AM web.1 |  pgSimple: getting tCznnEIuDbiwHSWVYXhbmJR-OFDLBcSR
# connect-pg-simple has completed the fetch query
12:02:29 AM web.1 |  query happened
# connect-pg-simple reports that it found nothing
12:02:29 AM web.1 |  no session found
# because the Google callback was successful, Passport redirects me to success
12:02:29 AM web.1 |  -----New request /success
# however, the fetch failed, and no session data was loaded. Therefore, Passport reports that I'm unauthenticated
12:02:29 AM web.1 |  authenticated: false
# finally, things end with connect-pg-simple announcing that it's about to create the session
12:02:29 AM web.1 |  pgSimple: creating
# and shortly after it finishes doing that
12:02:29 AM web.1 |  sessionIndex: save complete

I've confirmed that there aren't any hooks I could use to adjust the ordering. It seems to be the behavior of this library that's causing the issue. The cause seems pretty simple on the surface:

1. have no sessions stored, so that an authenticated request will need to be saved
2. set up a store with an async session.save method
3. successfully authenticate and run this middleware.
4. observe that session.save will be called
5. observe that the call to store.get is completely independent from the save; it can run and complete before save has completed

This seems pretty bad, if it's actually an issue. Though I'm sure it's more likely that I've just configured things incorrectly, as it would be very surprising if nobody else had run into this problem before.

[dougwilson]

So far, it doesn't look like there's any way for me to intercept this behavior; it all seems to happen in a few lines of code inside of this library's main function.

The behavior I am taking about should be in your code. When you are setting properties on re.session in your code, are you then calling res.redirect() or some other method to respond? What about the logout method, how are you actually responding yo the user, with a redirect?

If you are responding with a redirect, many web browsers will redirect before they even finish receiving the response. You can see if this is the case for you be not calling res.redirect until after the session has saved in your login routine. Example:

req.session.save(function () { res.redirect(...); });

The code you linked to is too complex for me to see on my phone and understand. Can you provide a case where this happens that does not use passport to rule out passport as the cause? Please link to a reproduction case. If you think you have found an issue,by all means, please feel free to provide pull request with a fix! Be sure to include a test that demonstrates the issue that failed without your change and passes with it :)

[mike-goodwin]

I saw a similar problem using my Azure table storage based session store (issue here). It only happened when the server was running locally because then the latency of the save operation was high. When running the server on Azure it never occurred. I "fixed" it by putting some hacky retry logic around the session getter, but I would like to fix it properly so that the get was not called until after the save has completed.

[jamesplease]

Long delay, but I spent today trying to figure this out. I wrote a huge step-by-step walkthrough of the issue over here, just to make sure I could pinpoint where the problem occurred.

@dougwilson 's comment above seems correct. It seems to be the case that express-session's automatic saving behaving when the request ends is unreliable in this situation, at least in Chrome. It doesn't actually delay the ending of the request, so the redirect occurs before the save completes.

As @dougwilson suggested, changing the redirect code to manually save before redirecting fixed the issue for me:

  app.get('/auth/google/callback', passport.authenticate('google', redirects),
  function(req, res) {
    // Explicitly save the session before redirecting!
    req.session.save(() => {
      res.redirect('/success');
    })
  });

@dougwilson , thanks for taking the time to think about this problem and offer what ended up being the solution!

[dougwilson]

Hi @jmeas, tanks for the follow up! I really like that write-up you posted and I think it will definitely help out a lot of other people! The redirect issue has been known about, though it's only been possible to just work-around the issue with the way the module is currently written. I have given this particular issue a lot of thought about how to fix it as we do a lot of rewriting for a 2.0 release sometime (this year?). For a long time, we were locked in 1.x while Express 3.x was supported, but I finished nailing that in a coffin, so to get us into a 2.0 world at some point.

[mjquito]

The workaround still leaves in calling the res.redirect.save() twice :(