Response Auth Headers and Batched Requests

[booleanbetrayal]

Hey @lynndylanhurley -

@nbrustein and I are investigating some issues involving multiple processes concurrently hitting API endpoints and occasionally causing logouts. The first grouping of issues seem to be fixed with some pessimistic locks around the user object in update_auth_header. We have this running in prod and it's definitely improved the situation. We'll plan on submitting a PR after a little more exposure, and some investigation behind how to unit test it.

The other issue we're seeing may result from a unreceived response while within a batched request window. It appears that update_auth_header sends the expected auth settings down on the response in every condition but this one, and I was wondering if there was a pragmatic reason for that. When tweaking that logic, I noticed that there were some tests (demo_user_controller_test.rb:199 and demo_mang_controller_test.rb:199) that explicitly check to ensure that the auth header are not returned. Was hoping you might be able to provide some insight into that. It seems that if we were always returning those headers, subsequent requests (still within the batch window) could update appropriately and not fail.

Thanks again for all the hard work! =]

[lynndylanhurley]

Hi @booleanbetrayal!

I'm really interested to see the pessimistic locking solution. I have seen that problem occur, but it happens so infrequently that I haven't been able to diagnose it.

Those tests (demo_user_controller_test.rb:199 and demo_mang_controller_test.rb:199) were implemented to address issue #17. If I recall correctly, the problem was that the responses weren't always returned in the order that the requests were made. This resulted in out-of-date access tokens incorrectly used by the client in subsequent requests.

The simplest fix was to only return new auth-tokens when they change. Another solution would be for the server to always return the latest auth-token, but for the client to only use the token if it has a later expiry date. Do you think this would fix the problem?

[booleanbetrayal]

I think that latter solution sounds the most robust, @lynndylanhurley . I can get a PR for the WIP stuff I have in this project. Would you want to drive the changes in ng-token-auth? I'm coffeescript challenged and have had some issues getting the specs running.

[lynndylanhurley]

@booleanbetrayal - I think I've solved this on the client-side. I'll run more tests tomorrow, and I'll push a release ASAP.

[booleanbetrayal]

Excellent! Thanks @lynndylanhurley

[otupman]

Thanks from me, too, @lynndylanhurley - I was just about to start digging deep to troubleshoot when I found this discussion.

I patched my local copy of ng-token-auth code with that fix up there and it works like a dream.

You made my evening soooo less stressful

👍 Thanks again!

[lynndylanhurley]

@otupman - thanks, I'll have a release ready soon!

[lynndylanhurley]

Check it out!

• ng-token-auth 0.0.24-beta2
• devise_token_auth 0.1.30.beta1

Please test and confirm that everything works!

[lynndylanhurley]

I'm getting a bunch of 401 errors on the demo site, mostly when making batched requests. This wasn't happening before this merge (to this degree anyway). I'll keep investigating, but let me know if you find anything.

[booleanbetrayal]

Boo ... The demo site's using the latest ng-token-auth as well? I'm out of the office today and probably won't be able to take a look until tomorrow. Will jump on it first thing if you haven't tracked it down by then.

[lynndylanhurley]

Ok I think I've found the problem. This one is tricky so I'll try to walk thru the problem step-by-step.

1. Two requests are made to the API at the same time.

2. The first request is processed using this code:

   auth_header = @user.create_new_auth_token(@client_id)
   # ...
   response.headers.merge!(auth_header)

   A new token is created and added to the response.

3. The response is returned to the client, and the new token is saved for the next request. Everything is fine up until this point.

4. The second request is processed by the API using this code:

   auth_header = @user.extend_batch_buffer(@token, @client_id)
   # ...
   response.headers.merge!(auth_header)

   The stale token from the original request is added to the response.

   This is where the problem begins. The @token value has expired at this point, and is only allowed because it was part of the batch request.

5. The second response is returned to the client, and because the expiry is later than the first request, the access token is saved, even though it is actually expired.

The problem is that expired tokens are sent back from the server as new tokens.

And we can't just read the latest token from the database, because it's impossible to re-construct a token once it's been hashed by BCrypt.

Creating a new token for each request isn't a solution because it will be prone to the same problem that this PR was trying to solve in the first place - if the wrong request is dropped, subsequent requests will fail authentication.

I'm going to push a quick fix to get this working as well as it was before this PR, but I don't have a real solution yet for the original issue.

[booleanbetrayal]

Maybe it's best to maintain a list of all acceptable tokens (rather than differentiating between current and last) that fall within the batch threshold, and continue to always re-issue? Let me know if you think that might work. We can keep this ticket open and brainstorm around it. I have some higher priority stuff to look at over the next couple of days, but perhaps we can re-visit?

[lynndylanhurley]

@booleanbetrayal - the problem is this (correct me if I'm wrong): we want all the responses in a batch request to return the latest token.

This is complicated because once the token is hashed and stored in the database, we lose the original value of the token.

So when a new token is generated for the first response in a batch request, how do we persist the original token value for the remaining requests in the batch?

[joshdvir]

Anything new about this?

I'm still having issues on this with 1.3.0

Also just to be sure, when i'm doing a request that is part of a batch request I get the same access token and also the same expiry?

Thanks

[mkhatib]

I am seeing the same symptoms but not entirely sure if it is the same problem. Every now and then the user is logged out, I am trying to debug and investigate a way to re-produce easily so I can test it out and see what's going on, but so far didn't manage to reproduce and seems happening at random steps.

Any idea if there's something to test for?

[astr0gator]

It looks like we have the same problem. Any ideas how to deal with it? Logouts are very frequent.
ng-token-auth#0.0.27
devise_token_auth-0.1.36

Would appreciate any help (even if it can only reduce logouts rate, not solve the problem as a whole).

[mkhatib]

Here's few ideas and data from doing some investigations - I am still not 100% sure these are the problems exactly, but hoping @lynndylanhurley might be able to jump to a conclusion to why these sudden invalid tokens happen.

I was able to reproduce this easily on locally. The web client does frequent requests to an authenticated endpoint - every 5 seconds intervals. I opened three web-clients in three different tabs and noticed after awhile the tokens that some clients are using are no longer valid and hence failing to authenticate. This was reproduced with varying values for batch buffer threshold config. Two of the clients where throttled to GPRS connection.

Possibility 1 - OLD (batch) Tokens overriding NEW Tokens on client

1. 3 requests (R1, R2, R3) going as one batch with the same token (T1).
2. The server successfully serves them using T1 and returns all of them with (T2).
3. R1 and R2 returns to the client and updates the client token to be T2.
4. Client updates token to T2.
5. Client makes new request R4 with new T2 token
6. Server processes R4 and return it with T3
7. Client updates token to T3
8. Server processes R5 and return it with T4
9. Client updates token to T4
10. R3 returns now to the client with T2 --- here where problem happens?
11. Client updates token to T2 (a very old token)
12. Any requests client makes now are going with T2
13. Server fails to authenticate any new requests because T2 is neither last_token nor current.

Possibility 2 - Batch Requests made by client takes too long to reach the server that it is no longer in the batch buffer threshold

This probably could be solved with increasing the buffer threshold.

Observation

When having multiple clients open, I observed some clients becoming invalid - and staying invalid using the same invalid token over and over again - while other clients successfully renewing.

I'll try to continue this investigation, any tips on where to look or what to keep an eye for or tips for debugging this in general would be helpful.

In general, the (bad) advice I saw in different places, including here - is to disable the renewing tokens on every request which seems to fix things of course.

[alimpaecher]

I am curious if this is considered resolved. I have difficult to reproduce logouts. Are there best practices on the client side to reduce or eliminate this problem?

[rmcsharry]

I have the same issue. I have a page that refreshes every 2 seconds and a mult-threaded server so responses do not always return in the same order. Sooner or later the Rails api starts to get unauthorised responses. It can also be easily triggered by the user reloading the app (which fires a few initialization calls to the api to get initial data, and if one of them gets cancelled - can happen - then an invalid token is returned).

Another way is that in my Angular client I can also add an interceptor that in some requests it does some work (eg. say a POST where it has to do some processing of the body) and others not. The POST can end up being returned after say a GET. The token for the POST is now seen as invalid by Rails and it returns a 401.

A similar issue is reported on the angular token library here.

I have also offered a 100 SO bounty on the question linked above by @mkhatib

[macgill4444]

We're running into this a lot. Some of our users are getting logged out up to 20 times a day. Others are logged out once a week. Any updates on this solution? What have people done to fix this? Thanks for your help and all your support with this project!