Invalid legacy session token after ParseUser.enableRevocableSessionInBackground

[alexblack]

Issue Description

Our Android users with multiple devices are permanently getting code=209, message=invalid legacy session token on all but one of their devices.

1. Users had several devices with our app installed
2. Our app was pointed at parse.com (not yet parse-server)
3. The users had a single ParseUser record, they were logged into it on each device, our app was not using revocable sessions
4. We updated our Android app, to switch to parse-server
5. The Android app on startup (every time) calls ParseUser.enableRevocableSessionInBackground()

What we see is:
a. The first device to update works fine
b. The other devices do not

So despite the other devices calling ParseUser.enableRevocableSessionInBackground(), they are still getting code=209, message=invalid legacy session token on all parse operations.

The only work around we've found is to get them to uninstall and reinstall the app on those devices.

Steps to reproduce

1. Install 0.1.229 of our Android app on two devices, this points to parse.com
2. In the Account section, on one app, create an account
3. In the Account section, on the other app, login to that account
4. Optional: create an invoice one device, confirm it syncs to other device
5. Update device 1 to 0.1.232, now the app points to our parse-server, and calls ParseUser.enableRevocableSessionInBackground()
6. See everything works fine
7. Update device 2 to 0.1.232
8. Get exception com.parse.ParseRequest$ParseRequestException: invalid session token when the app starts up, when it tries to call ParseUser.getCurrentUser().saveInBackground()

Expected result: apps on both devices work properly, and can do basic parse operations involving the ParseUser like saving it, saving other objects pointing to it etc

Environment Setup

• Server
  • parse-server version 2.2.22
  • using Express
  • Operating System: Android
  • Localhost or remote server? Heroku
• Database
  • Hosted at mLab
• Android app
  • parse sdk verison 1.13.1

Code

Before (parse.com): https://gist.github.com/alexblack/a2c8bdde59608e85f192448f8e4dde84
After (parse-server): https://gist.github.com/alexblack/8fd376d54c1535a5b8777cbbef4b82df

Logs/Trace

Exception: http://crashes.to/s/16792fdcd3d

{
     "client": {
          "name": "raygun-node",
          "version": "0.8.5"
     },
     "groupingKey": "code209messageinvalidsessiontoken",
     "error": {
          "message": "code=209, message=invalid session token"
     },
     "request": {
          "hostName": "invoice-simple.herokuapp.com",
          "url": "/parse/batch",
          "httpMethod": "POST",
          "ipAddress": "::ffff:10.186.80.249",
          "queryString": {},
          "headers": {
               "host": "invoice-simple.herokuapp.com",
               "connection": "close",
               "x-parse-os-version": "5.1",
               "x-parse-app-build-version": "2000359",
               "x-parse-client-version": "a1.13.1",
               "x-parse-app-display-version": "0.1.232",
               "x-parse-installation-id": "d3ca7c2a-60a9-4f44-9d46-d9391940d1cc",
               "user-agent": "Parse Android SDK 1.13.1 (com.aadhk.woinvoice/2000359) API Level 22",
               "x-parse-session-token": "voARgYrfgzc1SYKF7gm19Bmc8",
               "x-parse-application-id": "F8pgJyHm8jxQhXxYnpdEzBTxLP2Nhu68JLtmek3y",
               "content-type": "application/json",
               "accept-encoding": "gzip",
               "x-request-id": "1318fd32-036f-48b0-9ae0-a7fd2a7260b3",
               "x-forwarded-for": "114.125.12.147",
               "x-forwarded-proto": "http",
               "x-forwarded-port": "80",
               "via": "1.1 vegur",
               "connect-time": "0",
               "x-request-start": "1475892231454",
               "total-route-time": "0",
               "content-length": "499"
          },
          "form": {
               "requests": [
                    {
                         "method": "PUT",
                         "path": "/parse/classes/_Installation/UslVQbptng",
                         "body": {
                              "pushType": "gcm",
                              "deviceToken": "APA91bGFWQgXPnZoI6a4M369qGpKVfCrfLx0ajdSV0aihPCxwSWuXO-XtyB_TvnvyhiKO6eGNT5_VmEytJDP4CUhF_W-hNI6bXtKpJyihHm1XupvtUXz430fYwJYCBbaXOFYDOk4xoIa",
                              "appVersion": "0.1.232",
                              "parseVersion": "1.13.1",
                              "objectId": "UslVQbptng"
                         }
                    },
                    {
                         "method": "PUT",
                         "path": "/parse/classes/_User/3Ms85kJUin",
                         "body": {
                              "accountId": "9caae171f3654c95a7bfcba87c8b8639",
                              "countryCode": "id",
                              "objectId": "3Ms85kJUin"
                         }
                    }
               ]
          }
     },
     "machineName": "33f76be6-2c44-4a29-94db-eb8740cd37ba",
     "environment": {
          "osVersion": "Linux linux 3.13.0-95-generic",
          "architecture": "x64",
          "totalPhysicalMemory": 64426360832,
          "availablePhysicalMemory": 3063279616,
          "utcOffset": 0,
          "processorCount": 8,
          "cpu": "Intel(R) Xeon(R) CPU E5-2670 v2 @ 2.50GHz"
     },
     "userCustomData": {},
     "user": {},
     "tags": [],
     "OccurredOn": "2016-10-08T02:03:51.48Z"
}

Caused by: org.json.JSONException: Value {"code":209,"error":"invalid session token"} of type org.json.JSONObject cannot be converted to JSONArray
  at org.json.JSON.typeMismatch(JSON.java:111)
  at org.json.JSONArray.<init>(JSONArray.java:96)
  at org.json.JSONArray.<init>(JSONArray.java:108)
  at com.parse.ParseRESTObjectBatchCommand.onResponseAsync(ParseRESTObjectBatchCommand.java:163)
  ... 13 more


Inner throwable #1: com.parse.ParseRequest$ParseRequestException: bad json response
  at com.parse.ParseRequest.newTemporaryException(ParseRequest.java:290)
  at com.parse.ParseRESTObjectBatchCommand.onResponseAsync(ParseRESTObjectBatchCommand.java:167)
  at com.parse.ParseRequest$3.then(ParseRequest.java:137)
  at com.parse.ParseRequest$3.then(ParseRequest.java:133)
  at bolts.Task$15.run(Task.java:917)
  at bolts.BoltsExecutors$ImmediateExecutor.execute(BoltsExecutors.java:105)
  at bolts.Task.completeAfterTask(Task.java:908)
  at bolts.Task.continueWithTask(Task.java:715)
  at bolts.Task.continueWithTask(Task.java:726)
  at bolts.Task$13.then(Task.java:818)
  at bolts.Task$13.then(Task.java:806)
  at bolts.Task$15.run(Task.java:917)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
  at java.lang.Thread.run(Thread.java:761)
Caused by: org.json.JSONException: Value {"code":209,"error":"invalid session token"} of type org.json.JSONObject cannot be converted to JSONArray
  at org.json.JSON.typeMismatch(JSON.java:111)
  at org.json.JSONArray.<init>(JSONArray.java:96)
  at org.json.JSONArray.<init>(JSONArray.java:108)
  at com.parse.ParseRESTObjectBatchCommand.onResponseAsync(ParseRESTObjectBatchCommand.java:163)
  at com.parse.ParseRequest$3.then(ParseRequest.java:137) 
  at com.parse.ParseRequest$3.then(ParseRequest.java:133) 
  at bolts.Task$15.run(Task.java:917) 
  at bolts.BoltsExecutors$ImmediateExecutor.execute(BoltsExecutors.java:105) 
  at bolts.Task.completeAfterTask(Task.java:908) 
  at bolts.Task.continueWithTask(Task.java:715) 
  at bolts.Task.continueWithTask(Task.java:726) 
  at bolts.Task$13.then(Task.java:818) 
  at bolts.Task$13.then(Task.java:806) 
  at bolts.Task$15.run(Task.java:917) 
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133) 
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607) 
  at java.lang.Thread.run(Thread.java:761) 

[alexblack]

We've been unable to repro this on iOS

[alexblack]

Actually, we are seeing this on iOS too: http://crashes.to/s/743707c1b9c

Non-fatal: Error Domain: Parse Code: 101 NSLocalizedDescription: invalid session

Non-fatal: Error
0  Quick Service Estimates and Invoices    0x10039b99c CLSUserLoggingRecordError
1  Quick Service Estimates and Invoices    0x100382154 -[Crashlytics recordError:withAdditionalUserInfo:]
2  Quick Service Estimates and Invoices    0x1000e8b18 __42+[ParseHelper doParseStartupConfiguration]_block_invoke.52 (ParseHelper.m:73)
3  Quick Service Estimates and Invoices    0x1001a97f4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:412)
4  Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
5  Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
6  Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
7  Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
8  Quick Service Estimates and Invoices    0x1001aa75c -[BFTaskCompletionSource setError:] (BFTaskCompletionSource.m:53)
9  Quick Service Estimates and Invoices    0x1001a9ad0 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke_2 (BFTask.m:438)
10 Quick Service Estimates and Invoices    0x1001a97f4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:412)
11 Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
12 Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
13 Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
14 Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
15 Quick Service Estimates and Invoices    0x1001aa75c -[BFTaskCompletionSource setError:] (BFTaskCompletionSource.m:53)
16 Quick Service Estimates and Invoices    0x1001a9ad0 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke_2 (BFTask.m:438)
17 Quick Service Estimates and Invoices    0x1001a97f4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:412)
18 Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
19 Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
20 Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
21 Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
22 Quick Service Estimates and Invoices    0x1001aa75c -[BFTaskCompletionSource setError:] (BFTaskCompletionSource.m:53)
23 Quick Service Estimates and Invoices    0x1001a9ad0 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke_2 (BFTask.m:438)
24 Quick Service Estimates and Invoices    0x1001a98b4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:446)
25 Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
26 Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
27 Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
28 Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
29 Quick Service Estimates and Invoices    0x1001aa75c -[BFTaskCompletionSource setError:] (BFTaskCompletionSource.m:53)
30 Quick Service Estimates and Invoices    0x1001a9ad0 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke_2 (BFTask.m:438)
31 Quick Service Estimates and Invoices    0x1001a97f4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:412)
32 Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
33 Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
34 Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
35 Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
36 Quick Service Estimates and Invoices    0x1001aa75c -[BFTaskCompletionSource setError:] (BFTaskCompletionSource.m:53)
37 Quick Service Estimates and Invoices    0x1001a9ad0 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke_2 (BFTask.m:438)
38 Quick Service Estimates and Invoices    0x1001a97f4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:412)
39 Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
40 Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
41 Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
42 Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
43 Quick Service Estimates and Invoices    0x1001aa75c -[BFTaskCompletionSource setError:] (BFTaskCompletionSource.m:53)
44 Quick Service Estimates and Invoices    0x1001a9ad0 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke_2 (BFTask.m:438)
45 Quick Service Estimates and Invoices    0x1001a97f4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:412)
46 Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
47 Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
48 Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
49 Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
50 Quick Service Estimates and Invoices    0x1001aa75c -[BFTaskCompletionSource setError:] (BFTaskCompletionSource.m:53)
51 Quick Service Estimates and Invoices    0x1001a9ad0 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke_2 (BFTask.m:438)
52 Quick Service Estimates and Invoices    0x1001a98b4 __55-[BFTask continueWithExecutor:block:cancellationToken:]_block_invoke (BFTask.m:446)
53 Quick Service Estimates and Invoices    0x1001a6a3c __29+[BFExecutor defaultExecutor]_block_invoke_2 (BFExecutor.m:66)
54 Quick Service Estimates and Invoices    0x1001a6f9c -[BFExecutor execute:] (BFExecutor.m:131)
55 Quick Service Estimates and Invoices    0x1001a93e8 -[BFTask runContinuations] (BFTask.m:384)
56 Quick Service Estimates and Invoices    0x1001a8f28 -[BFTask trySetError:] (BFTask.m:323)
57 Quick Service Estimates and Invoices    0x1001aa988 -[BFTaskCompletionSource trySetError:] (BFTaskCompletionSource.m:78)
58 Quick Service Estimates and Invoices    0x100274ee4 -[PFURLSessionDataTaskDelegate _taskDidFinish] (PFURLSessionDataTaskDelegate.m:78)
59 Quick Service Estimates and Invoices    0x1002765a0 -[PFURLSessionJSONDataTaskDelegate _taskDidFinish] (PFURLSessionJSONDataTaskDelegate.m:88)
60 Quick Service Estimates and Invoices    0x1002753a8 -[PFURLSessionDataTaskDelegate URLSession:task:didCompleteWithError:] (PFURLSessionDataTaskDelegate.m:156)
61 Quick Service Estimates and Invoices    0x1002729ec -[PFURLSession URLSession:task:didCompleteWithError:] (PFURLSession.m:233)
62 CFNetwork                               0x193df86e8 __51-[NSURLSession delegate_task:didCompleteWithError:]_block_invoke.185
63 Foundation                              0x1941097e4 __NSBLOCKOPERATION_IS_CALLING_OUT_TO_A_BLOCK__
64 Foundation                              0x19404e358 -[NSBlockOperation main]
65 Foundation                              0x19403e954 -[__NSOperationInternal _start:]
66 Foundation                              0x19410bb90 __NSOQSchedule_f
67 libdispatch.dylib                       0x1924d11c0 _dispatch_client_callout
68 libdispatch.dylib                       0x1924df444 _dispatch_queue_serial_drain
69 libdispatch.dylib                       0x1924d49a8 _dispatch_queue_invoke
70 libdispatch.dylib                       0x1924e138c _dispatch_root_queue_drain
71 libdispatch.dylib                       0x1924e10ec _dispatch_worker_thread3
72 libsystem_pthread.dylib                 0x1926d92c8 _pthread_wqthread
73 libsystem_pthread.dylib                 0x1926d8db4 start_wqthread

[flovilmart]

Can you provide the server logs associate with that issue (when running with VERBOSE=1) and the steps to reproduce?

[alexblack]

Server logs - yeah I can probably do that.

Steps to repro - I did provide some, are they not acceptable?

[flovilmart]

I'll know more with the server logs.

[alexblack]

This issue has now affected at least 1,151 of our users on iOS http://crashes.to/s/95c28529e47 and 1,245 users on Android http://crashes.to/s/f1ea38ce61c.

Logs:

1. Device 1 updates to new app version, pointing to parse-server now (works fine)
2. Parse-server logs: http://pastebin.com/raw/MpDjBQwF
3. Gradle logs: http://pastebin.com/raw/pNHA0kNr
4. Device 2 updates to new app version, pointing to parse-server now (hits 209 invalid session token issue)
5. Parse-server logs: http://pastebin.com/raw/Z8AdaWkq
6. Gradle logs: http://pastebin.com/raw/u5BrUsS7

As you can see there is basically no info in the heroku logs for parse-server on what went wrong for device 2... any ideas? VERBOSE is on as you can see in the logs from device 1

[flovilmart]

I see that in your second logs, the server response is 400 (http://pastebin.com/raw/Z8AdaWkq). I don't believe this is the right server being hit as it doesn't even seem to pass the heroku router. There's not log involving parse-server failing to upgrade your token or else.

[alexblack]

Its the same server. I'm watching it live with heroku logs --tail

[flovilmart]

ok, so I see in the cradle logs: invalid legacy session token in that case you should prompt the user to login again. Unless you're 100% sure the session token is still on the User object, in which case this is a problem in the code.

See the test suite: https://github.com/ParsePlatform/parse-server/blob/ad707457be13f177e4a0dc481c990ddbd2df8d80/spec/RevocableSessionsUpgrade.spec.js#L72

[alexblack]

Yes, thats the issue we're facing, see the issue desc above. Yes, that works around the issue.

Please help fix the issue.

1. parse-server is doing a terrible job at logging, no error logged.
2. parse-server should not respond with invalid session token in this scenario. it should accept the requests.

[flovilmart]

It should not accept the requests, as you're passing an explicitly bad session token... This is to match the behaviour with parse.com.

We should never let a bad session token make request.

Yes, that works around the issue

That's not a workaround, that's the expected behaviour...

[alexblack]

I'd appreciate some context with your comments. We're using the Android and iOS SDK, they are passing the token, not us.

What did we do wrong? I don't think we did anything wrong. But if you do, please just specify what it is.

[alexblack]

Also, please respond to my point about parse-server doing a terrible job logging. This is not helpful:

2016-10-20T18:05:29.387223+00:00 heroku[router]: at=info method=POST path="/parse/upgradeToRevocableSession" host=invoice-simple-staging.herokuapp.com request_id=900d385f-cbeb-4ea9-a3eb-040e2d435dc0 fwd="50.67.170.54" dyno=web.1 connect=0ms service=20ms status=400 bytes=579
2016-10-20T18:05:29.626454+00:00 heroku[router]: at=info method=PUT path="/parse/classes/_User/Im6T4nuJOY" host=invoice-simple-staging.herokuapp.com request_id=67f0f81f-5474-4e10-a1bb-1d59890db06c fwd="50.67.170.54" dyno=web.1 connect=1ms service=36ms status=400 bytes=572
2016-10-20T18:05:29.817709+00:00 heroku[router]: at=info method=POST path="/parse/classes/Event" host=invoice-simple-staging.herokuapp.com request_id=edf76ef6-455a-4859-b2f8-9d01a4e60975 fwd="50.67.170.54" dyno=web.1 connect=1ms service=30ms status=400 bytes=572
2016-10-20T18:05:30.244283+00:00 heroku[router]: at=info method=PUT path="/parse/classes/_User/Im6T4nuJOY" host=invoice-simple-staging.herokuapp.com request_id=d5ea0e5f-bbc3-4533-addc-f9556b029746 fwd="50.67.170.54" dyno=web.1 connect=2ms service=32ms status=400 bytes=572
2016-10-20T18:05:35.518389+00:00 heroku[router]: at=info method=POST path="/parse/events/AppOpened" host=invoice-simple-staging.herokuapp.com request_id=f92df5a4-c7c7-44e3-8bd1-e866b5e360a3 fwd="50.67.170.54" dyno=web.1 connect=1ms service=39ms status=400 bytes=572
2016-10-20T18:05:37.493175+00:00 heroku[router]: at=info method=PUT path="/parse/classes/_User/Im6T4nuJOY" host=invoice-simple-staging.herokuapp.com request_id=577bd3fa-7f02-4ae3-9160-32960f9242cd fwd="50.67.170.54" dyno=web.1 connect=0ms service=95ms status=400 bytes=572

[alexblack]

That's not a workaround, that's the expected behaviour...

Please elaborate. We migrated from parse.com to parse-server, for any of users with multiple devices, the first device to migrate works fine, the second one receives the 209 invalid session token error.

This has left thousands of our users screwed. What did we do wrong that causes our user's second devices to get this error?