invalid session token code=209, message=invalid session token on v2.3.7

[mman]

Issue Description

I have started getting the error invalid session token code=209, message=invalid session token after upgrading to 2.3.7 earlier today. Looking at now closed bug #2255 and at the source code the root cause seems to be that there are two session ids present for the same user and same installation id created and updated around the same time.

Not all API calls generate this error and not all users are affected.

Steps to reproduce

Not sure, I'm continuously updating parse-server every few weeks to keep with the latest releases, the message started popping up after upgrading to 2.3.7.

Logs/Trace

This is one of the requests that generates the error message:

d61952fe52b4[1182]: #033[36mverbose#033[39m: REQUEST for [PUT] /xxx/classes/_User/HngzyE3Clx: {
d61952fe52b4[1182]:   "runCount": {
d61952fe52b4[1182]:     "__op": "Increment",
d61952fe52b4[1182]:     "amount": 1
d61952fe52b4[1182]:   },
d61952fe52b4[1182]:   "lastContact": {
d61952fe52b4[1182]:     "iso": "2017-03-21T12:01:55.180Z",
d61952fe52b4[1182]:     "__type": "Date"
d61952fe52b4[1182]:   }
d61952fe52b4[1182]: } method=PUT, url=/xxx/classes/_User/HngzyE3Clx, host=xxx, connection=close, content-length=109, x-parse-app-display-version=4.0.2, x-parse-application-id=unused, accept=*/*, x-parse-os-version=9.3.5 (13G36), accept-language=en-us, x-parse-client-key=unused, user-agent=XXX/348 CFNetwork/758.5.3 Darwin/15.6.0, x-parse-app-build-version=348, content-type=application/json; charset=utf-8, x-parse-session-token=r:97ee17db8bc95ad6b657abb84aec39cb, x-parse-client-version=i1.14.2, x-parse-installation-id=bcf5b055-3b1c-4dc2-a405-5e04a5a1c3ad, accept-encoding=gzip, deflate, __op=Increment, amount=1, iso=2017-03-21T12:01:55.180Z, __type=Date
d61952fe52b4[1182]: #033[36mverbose#033[39m: RESPONSE from [PUT] /xxx/classes/_User/HngzyE3Clx: {
d61952fe52b4[1182]:   "response": {
d61952fe52b4[1182]:     "runCount": 76,
d61952fe52b4[1182]:     "updatedAt": "2017-03-21T12:01:55.668Z"
d61952fe52b4[1182]:   }
d61952fe52b4[1182]: } runCount=76, updatedAt=2017-03-21T12:01:55.668Z
d61952fe52b4[1182]: #033[31merror#033[39m: invalid session token code=209, message=invalid session token

This is the query for all sessions for that user

rs0:PRIMARY> db.getCollection('_Session').find({"_p_user":"_User$HngzyE3Clx"})
{ "_id" : "4sQEyDhudw", "_session_token" : "r:e7500d9da1f7ea868e0e21c14b9cd83e", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-03T09:29:19.181Z"), "installationId" : "2b907a0c-26eb-4f19-bd6b-8dd7a734ec0c", "_created_at" : ISODate("2017-01-03T09:29:19.182Z"), "_updated_at" : ISODate("2017-01-03T09:29:19.182Z") }
{ "_id" : "Hn4AKvsUHi", "_session_token" : "r:e5e605f07e51c57de3e4601d3245aa34", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-03T09:29:19.201Z"), "installationId" : "2b907a0c-26eb-4f19-bd6b-8dd7a734ec0c", "_created_at" : ISODate("2017-01-03T09:29:19.202Z"), "_updated_at" : ISODate("2017-01-03T09:29:19.202Z") }
{ "_id" : "NwZxUuYmZt", "_session_token" : "r:3f9876c47dd44257afafed29c9203fd9", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-04T10:35:34.458Z"), "installationId" : "710680df-6519-42be-a675-d0dab62cdee5", "_created_at" : ISODate("2017-01-04T10:35:34.458Z"), "_updated_at" : ISODate("2017-01-04T10:35:34.458Z") }
{ "_id" : "SbwP8G7jDQ", "_session_token" : "r:f8b307985b8c4ebed1330202aa30594a", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-04T10:35:34.453Z"), "installationId" : "710680df-6519-42be-a675-d0dab62cdee5", "_created_at" : ISODate("2017-01-04T10:35:34.453Z"), "_updated_at" : ISODate("2017-01-04T10:35:34.453Z") }
{ "_id" : "BVMouretHK", "_session_token" : "r:25d3e52c371386b56e96d0f9b839c287", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-05T01:30:30.838Z"), "installationId" : "bcf5b055-3b1c-4dc2-a405-5e04a5a1c3ad", "_created_at" : ISODate("2017-01-05T01:30:30.838Z"), "_updated_at" : ISODate("2017-01-05T01:30:30.838Z") }
{ "_id" : "iHVJWkOFsV", "_session_token" : "r:97ee17db8bc95ad6b657abb84aec39cb", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-05T01:30:30.864Z"), "installationId" : "bcf5b055-3b1c-4dc2-a405-5e04a5a1c3ad", "_created_at" : ISODate("2017-01-05T01:30:30.864Z"), "_updated_at" : ISODate("2017-01-05T01:30:30.864Z") }
{ "_id" : "SxZux6gBcs", "_session_token" : "r:748b0629fad3537c64bdff4f16eb66b6", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "signup", "authProvider" : "password" }, "restricted" : false, "installationId" : "c48adf7f-7b67-4a68-a7b0-91422c3141d2", "expiresAt" : ISODate("2018-01-03T09:25:13.906Z"), "_created_at" : ISODate("2017-01-03T09:25:13.906Z"), "_updated_at" : ISODate("2017-01-03T09:25:13.906Z") }
{ "_id" : "wVY87z45Rd", "_session_token" : "r:1aaa34b479dbc40a98b92895fde3c210", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-02-23T13:12:54.912Z"), "installationId" : "ee8b543c-3108-43ef-85e8-383614581082", "_created_at" : ISODate("2017-02-23T13:12:54.912Z"), "_updated_at" : ISODate("2017-02-23T13:12:54.912Z") }
{ "_id" : "YQ8jGPOkdy", "_session_token" : "r:501c602c40834ef82637300847ce0d3d", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-02-23T13:12:55.494Z"), "installationId" : "ee8b543c-3108-43ef-85e8-383614581082", "_created_at" : ISODate("2017-02-23T13:12:55.494Z"), "_updated_at" : ISODate("2017-02-23T13:12:55.494Z") }

If you look at the session for installation id bcf5b055-3b1c-4dc2-a405-5e04a5a1c3ad they are actually just few milliseconds apart which looks weird...

{ "_id" : "BVMouretHK", "_session_token" : "r:25d3e52c371386b56e96d0f9b839c287", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-05T01:30:30.838Z"), "installationId" : "bcf5b055-3b1c-4dc2-a405-5e04a5a1c3ad", "_created_at" : ISODate("2017-01-05T01:30:30.838Z"), "_updated_at" : ISODate("2017-01-05T01:30:30.838Z") }
{ "_id" : "iHVJWkOFsV", "_session_token" : "r:97ee17db8bc95ad6b657abb84aec39cb", "_p_user" : "_User$HngzyE3Clx", "createdWith" : { "action" : "login", "authProvider" : "password" }, "restricted" : false, "expiresAt" : ISODate("2018-01-05T01:30:30.864Z"), "installationId" : "bcf5b055-3b1c-4dc2-a405-5e04a5a1c3ad", "_created_at" : ISODate("2017-01-05T01:30:30.864Z"), "_updated_at" : ISODate("2017-01-05T01:30:30.864Z") }

Please let me know if you need more details.

[flovilmart]

The description is pretty clear, thanks for the report. Do you by any chance have:

• http requests logs (to see is 2 fast consecutive requests triggered it)?
• any cloudcode hook on _Session that could perhaps be problematic?

[mman]

No cloudcode, just an iOS SDK from September, I'm trying to gather how many session rows are duplicated and looks like quite a lot... I'm trying to find some recent duplicates so that I can find the matching HTTP calls...

[mman]

I don't have the detailed HTTP logs but I think this is what it looks like:

Mar 15 05:08:30 7aebaf975668[870]: 107.77.213.176 - - [15/Mar/2017:04:08:30 +0000] "POST /xxx/login HTTP/1.1" 200 415 "-" "XXX/348 CFNetwork/808.2.16 Darwin/16.3.0"
Mar 15 05:08:30 7aebaf975668[870]: 107.77.213.176 - - [15/Mar/2017:04:08:30 +0000] "POST /xxx/login HTTP/1.1" 200 415 "-" "XXX/348 CFNetwork/808.2.16 Darwin/16.3.0"

[mman]

Just for the record I have now downgraded back to 2.3.2 which I know is not generating the message as I'm not yet sure whether the error 209 is not logging my users out as a side effect.

I think the questions that I have for the moment:

1. Looks like duplicate sessions are generated by quick successive POST /login HTTP requests. If this is indeed true, parse server should update the existing session and not create another row. Correct? What would be the fix here assuming client side (iOS app) can not be updated reasonably quickly?

2. Will the error 209 generated as a result of an API call cause the client parse SDK to logout the user? Or can it be considered harmless?

3. What would be the best way to fix the database? cleanup all duplicate sessions by deleting the one with older _updated_at timestamp for example?

thanks for your help, Martin

[flovilmart]

should update the existing session and not create another row

The problem with that is that when the login occurs twice, no session is recorded in the database yet.

Will the error 209 generated as a result of an API call cause the client parse SDK to logout the user

It should be 'harmless' but no guarantee for sure.

cleanup all duplicate sessions by deleting the one with older _updated_at timestamp for example

that seems reasonable. But you can't guarantee for sure if you won't delete the session token being used. As this is a race condition, there's no way to know for sure which session token is being used. from the _Session table.

Do you have a lot of duplicates in the DB?

[mman]

I'm using this query to find out duplicates by I'm not a mongo expert so I have not yet found out how to actually count how many users are affected. Do you know how to modify the group aggregate to return how many sessions are duplicated?

db.getCollection('_Session').aggregate( { $group: { _id: { "installationId": "$installationId", "_p_user": "$_p_user" }, count: { $sum: 1}, docs: { $push: "$_id" }}}, { $match: { count: { $gt: 1 }}})

[mman]

To confirm. I have now been able to reproduce the problem and it is indeed a bug in my iOS app where certain conditions trigger double login API call.

[flovilmart]

nice, you should fix it too :) we can find a workaround in the same time.

[mman]

Bug fixed and retested in the app beta, but it will take many months before it will spread to the users.

In the meantime due to the nature of the bug hitting the /login API endpoint twice from the same device quickly many devices will be duplicating my session rows over time.

I see two ways forward:

1/ Investigating what exactly is happening on the Parse iOS SDK side when it receives error 209 as a result of any API call, to assess the potential damage to the client. If harmless leave as is and ignore. If not harmless go to 2/

2/ Modify Auth.js line 59 to not throw on finding multiple sessions for the same installation id and same user and proceed with one session.

What do you think would be the best way forward?

[steven-supersolid]

You could also add a unique index to _Session on installationId and _p_user but will need to fix your existing bugged sessions first. This is also something that could be added to parse-server in a similar way to there being unique indexes on _User. It would have the benefit that the database could not get in a broken state and then I think it would be safe to remove the line from Auth.js.

If the checking in Auth.js is not doing anything useful then could be removed too as it looks more of a hindrance right now when the _Session collection is in a broken state.

[flovilmart]

That would be only on Installation, for uniqueness, as a user can have multiple sessions

[steven-supersolid]

I mean something like the following so only the compound index is unique: db.getCollection("_Session").createIndex({"installationId": 1, "_p_user": 1 }, {unique:true})

This should allow a user to have multiple sessions as long as the installationId is different for each one.

Or would that not work?

[flovilmart]

uhm right, that could work :)

[mman]

Creating a unique index across installationId and _p_user will definitely ensure there could be no duplicate session for the same installation, but what would happen in my case where two consecutive POST /login API calls arrive at around the same time? as in my buggy app?

I assume the first /login that gets a chance to write new session will succeed, and the second /login will fail to insert session and will thus fail.

Do I understand it correct?

[flovilmart]

the second login would fail yes, and that's not what we want or do we?

[steven-supersolid]

I think it should ideally fail but not sure how your app will handle that.

We had a similar issue with creating duplicate users with the same anonymous id, in which case we added an index on _User. It was better to return an error and deal with it than have to deal with duplicates in the database down the line. However, we use cloud code for all client calls so it was easy to update the error handling for this.

If the login requests are concurrent then it is going to be difficult to prevent this happening in code as when parse-server creates the sessions there will be no duplicates as far as each concurrent thread is concerned. We would have to perform a query after session creation and if there is a duplicate then delete one of them. We would have to make sure both concurrent threads played nice with this deletion, i.e. they don't both delete their own session! The thread that has its session deleted would have to return the session of the other thread.

This is why unique indexes are simpler but it moves responsibility to the client.

[flovilmart]

Yes I would agree with that, but in a sense, login twice is not 'bad' it's still valid as any of the login call is successful. Which can be more problematic client-side as the SDK may log the user out.

OR we should treat session creations as 'upsert' instead of inserts no?

[steven-supersolid]

I'm not 100% sure on the parse rules for multiple logins from the same installationId. If it can only happen in this edge case of concurrent login then perhaps we can live with it as it is valid to have multiple sessions per _User anyway.

https://github.com/ParsePlatform/parse-server/blob/master/src/Auth.js#L59 Looking again at the code, if looks like there will be an error if there is a duplicate session token but that is not the case here. The error must be returned somewhere else.

The upsert may help but I'm not sure what happens when called concurrently.

[mman]

Looking at the situation from the client side API I think the issue resolves around what should login do when there is already a logged in user.

Either silently succeed, or fail with "error: already signed in, logOut first before doing another login".

I understand all the reasoning and technical details behind this, and I'm fine with either solution. I'd say let's choose the one that makes things easier and more transparent to implement and understand later from the maintenance perspective.

[flovilmart]

We can definitely let go through when multiple valid sessions are found. That would solve the issue.

[flovilmart]

@mman do you want to try open a PR for that issue?

[mman]

@flovilmart I have taken two days to let the idea settle down a bit and to think about potential implementation given my limited knowledge of the parse server internals.

I'm now inclined to suggest that the server should allow multiple sessions per user and device as there is no easy way to allow only one session per user / device without some kind of locking and/or making the second login fail and thus impose a change on the existing apps using existing SDK. So preserving the current client SDK behavior when the underlying parse server changes is a reasonable requirement.

If we agree on that I'll have to find how the server behaved in 2.3.2 which is the last version that I know works for me without generating error messages and any side effects.

I will not have a chance to take a look at this for the next two weeks though. If you have the fix in your head I'll be happy to review and deploy the master once the fix is in and quickly verify whether everything works as expected. Otherwise I'll try to take a look later.

thanks for your help, Martin

[flovilmart]

I'll have a look, we should properly handle those cases.

[RafaRuiz]

are we taking in consideration what we said in: https://github.com/parse-community/parse-server/issues/2255 ??

I was able to reproduce the bug in earlier versions, not in v2.3.7, but it came back again (can't reproduce it like the old way, but it seems it's back!) It's a little bit annoying, I had to restart my server twice, and it's in production :(

[flovilmart]

@RafaRuiz we need to let multiple sessions for a single installationId, this may happen if multiple login calls are run right after one other.

Perhaps we can investigate this $isolated operator

[mman]

Just to continue the investigation, I have rebuilt my servers to 2.3.8 and the error message is still there. Looking at the code carefully again the code 209 with the identical exception error message is also thrown from handleMe method in the UsersRouter.js (https://github.com/parse-community/parse-server/blob/29fec01a42dd58b05d0a3d8220df4555bb44d89a/src/Routers/UsersRouter.js#L43)

Could you please help me figure out which API call could lead to this? Enabling VERBOSE=1 does produce a lot of output but I'd need something that that would help me understand where is this coming from...

[RafaRuiz]

I've been doing my debugging but I can't send a pull request because I'm not really an expert in this, is anyone looking at this? I have to restart around every day or every two days, and users are just uninstalling my app:

[flovilmart]

Have you indexed correctly the _Session table?

[RafaRuiz]

@flovilmart the _Session table is indexed with

but it's not the only one, this is the list:

anything wrong with it?

[derekvanvliet]

Hey guys any update on this? We just launched a game using 2.3.8 and I think we're getting bitten by this too. In our case when the 209 response is returned the game starts a new session, effectively losing all their progress.

[flovilmart]

@derekvanvliet can you isolate the request/responses that trigger those 209?

[derekvanvliet]

@flovilmart Yes, here's an example of what I'm seeing in my log:

`verbose: REQUEST for [GET] /1/users/me: {} method=GET, url=/1/users/me, host=example.com, x-real-ip=xx.xx.xx.xx, x-forwarded-for=xx.xx.xx.xx, xx.xx.xx.xx, accept=/, accept-encoding=gzip, deflate, accept-language=pt-pt, content-type=application/x-www-form-urlencoded, user-agent=UE4-RUA3,UE4Ver(4.15.2-0+++UE4+Release-4.15), x-parse-application-id=MyAppId, x-parse-rest-api-key=MyRestApiKey, x-forwarded-port=443, x-forwarded-proto=https,

error: Error handling request: ParseError { code: 209, message: 'invalid session token' } code=209, message=invalid session token  [31merror: invalid session token code=209, message=invalid session token `

The first thing that stuck out to me is that a session token isn't included in the request. But I've reviewed our client side code several times now and I don't see a way that it is not sending a session token.

[flovilmart]

I don't see a way that it is not sending a session token

So that's probably in the SDK or a previous call would have overriden the session token, we're making progress. That's good.

Impossible to know which user made that request (as we don't have the token); What SDK are you using?

[derekvanvliet]

@flovilmart this is using the REST API

[flovilmart]

So, you're sending a call to /users/me without a sessionToken, not sure how to help...

[mman]

Just to update you guys, I'm watching this and all my investigation is pointing towards this error message being generated via GET /users/me.

The strange thing is that I'm seeing this less with the latest 2.3.8 without me changing anything, and I can't identify an API call in the nginx logs that would not return HTTP 1.1 200 when this message drops in the parse logs. In fact I don't see any API calls towards /users/me in the logs at all. And I can't find a place where we would use /users/me in our code.

So I have not forgotten this, it just seems to be very hard to debug :)

[flovilmart]

@mman what SDK's are you using?

[mman]

@flovilmart It's 1.8.5 because of it being the last that supports iOS 7 IIRC

[flovilmart]

Thanks for tracking that down, I know where to focus the investigation now. By any chance, can you find a faulty iOS installation that triggers that issue, and relaunch it with request tracing? https://github.com/parse-community/Parse-SDK-iOS-OSX/wiki/Network-Debug-Tool

[mman]

I will not be able to alter the client side easily, but I can play with the server so I can dump the request headers and response on the parse-server side. The only missing point is how to track down where is the error message coming from. Simply enabling VERBOSE=1 produces a lot of output - which is expected - but I can't find a clue as to what request actually generated the error. I'm looking for something similar to Java's Exception.printStackTrace() that dumps the call stack at the moment error is printed or some even more verbose option that would track the request processing in more detail in the server...

do we have something more detailed than VERBOSE=1?

[flovilmart]

You can probably put the express logger, but I don't believe we need more detailed logs. Seems to be because the client is not sending it's session token, which would be because the session token is not sent from the client.

[RafaRuiz]

For anyone that could be interested.

Since there's no fix for this yet, I created a python script that checks a random endpoint that never would return 209 and, if it does, it restarts the server.

crontab -e: (checks every minute) */1 * * * * python /parse-server/PronuntiaTests/Pronuntia209.py

Pronuntia209.py:

import requests
import json
import subprocess
import datetime

urlForTest = "https://pronuntiapp.com:1338/parse/functions/{yourCloudFunctionHere}";

payload = { }
headers = { 'X-Parse-Application-Id' : '{yourParseAppIdHere}',
                        'X-Parse-REST-API-Key' : '{yourParseAPIKeyHere}',
                        'Content-Type' : 'application/json',
                        'X-Parse-Session-Token' : '{INCLUDE A SESSION TOKEN, grab it from the table, be sure that it belongs to an user, otherwise it wont work' }

res = requests.post(urlForTest, data=payload, headers=headers)
result = json.loads(res.text);

message = "[" + str(datetime.datetime.now()).split('.')[0] + "] "
try:
        code = result["code"]
        if code == 209:
                message += "GOT 209! restarting server"
                // change this for your script to restart the server. In my case, the bin is forever, arg1 = restart, arg2 = location of the index.js
                subprocess.check_output(['forever', 'restart', '/parse-server/index.js'])
        else:
                message += "GOT " + str(code) + ". Not restarting the server"

except KeyError:
        message += "GOT unknown error, this is the result: " + str(result)

// This will write a file for you that indicates a timestamp and what happened (whether if was restarted or not)
text_file = open("/tmp/ParseStatus.txt", "a")
text_file.write(message + "\n")
text_file.close()

[flovilmart]

There is no fix (yet) because we're unsure what the issue is or what yields it.

[mman]

@RafaRuiz Exactly as @flovilmart says. The problem is real, I don't know where is it coming from and what bad is it doing - if anything. I have it in production for two weeks now and it does not seem to have any negative side effects. In any case, restart is not making it disappear or show less.

[flovilmart]

@mman did you had old non révocable session tokens that you upgraded with parse-server and not parse.com?

[flovilmart]

Also, we dropped support for iOS 8 6 months ago in my current company, do you have any plan to bump the SDK and your minimum iOS version?

[mman]

@flovimart I don't know about non-revocable sessions, but there definitely were users using the app with some old SDK against parse.com that at some point in time upgraded to the new SDK and new parse server. Assuming (read I have no idea) the new SDK simply took the saved settings on the device it might explain your hypothesis.... but... it's still confusing to me that I don't see any 4xx or 5xx error codes in the log in addition to 209, like the javascript error is being ignored in fact.

To answer the minimum iOS requirement. Given the nature of our app I intend to support iOS 7 as long as possible so I will either stick with old client SDK version or will roll our own in house fork to keep compatibility...

I forgot to mention that I have another app that is iOS8 + on iOS SDK 1.14.2 and that has been released from day one running against our own parse server and that works great and without any errors.

[flovilmart]

@mman So those 209 errors are only generated form requests coming from the old SDK?

[RafaRuiz]

I know that it's not fixed, I was trying to help you guys in case you don't want to have the server throwing 209 unexpectedly.

In my case the 209 are coming from anywhere, using JS SDK, Android SDK and iOS SDK

[flovilmart]

What endpoint is returning it? Is it in the auth middleware? As @mman mentions, with a recent iOS SDK it doesn't seem to be an issuez