OAuth 2 refresh tokens expire early

[Dagefoerde]

Somehow, OAuth2 refresh tokens seem to expire. It's probably fine if they would in the long run, but this is happening within a few hours.

Steps to reproduce

1. Authenticate an OAuth client and upgrade the authorization code in order to obtain access token and refresh token
2. Wait for a couple of hours (6 p.m. to 9 a.m. seems to be sufficient)
3. Try to obtain a new access token using the refresh token

Expected behaviour

Access tokens expire after an hour. In contrast, refresh tokens should be valid for a while; let's say for a week? I am happy to discuss this, though...

Actual behaviour

First of all, I changed OauthApiController.php and enumerated the invalid_request responses, i.e., the first occurrence is invalid_request1, the second is invalid_request2, and the third is invalid_request3.
The response of /index.php/apps/oauth2/api/v1/token is a 400 with the following content:

{
    "error": "invalid_request3"
}

Subsequent requests with the same refresh token result in invalid_request1. This implies that, the first time we end up here:

server/apps/oauth2/lib/Controller/OauthApiController.php

Line 140 in a1ea504

} catch (InvalidTokenException $e) {

Whereas, subsequently, we end up here:

server/apps/oauth2/lib/Controller/OauthApiController.php

Line 107 in a1ea504

} catch (AccessTokenNotFoundException $e) {

Using mitmproxy, I was able to intercept this request:

Server configuration

Operating system: Ubuntu 16.04.5 LTS

Web server: Apache/2.4.18 (Ubuntu)

Database: Postgres 9.5.14

PHP version: 7.0.32-0ubuntu0.16.04.1

Nextcloud version: 14.0.3.0

Updated from an older Nextcloud/ownCloud or fresh install: updated

Where did you install Nextcloud from: nextcloud.com

Are you using external storage, if yes which one: no

Are you using encryption: no

Logs

Nextcloud log (data/nextcloud.log)

Nextcloud log

{"reqId":"QZyVyb5XHzpDByur1vNi","level":2,"time":"2018-10-19T07:52:25+00:00","remoteAddr":"128.176.157.47","user":"--","app":"core","method":"POST","url":"\/nextcloud\/index.php\/apps\/oauth2\/api\/v1\/token","message":"Login failed: '<client id omitted>' (Remote IP: '128.176.157.47')","userAgent":"MoodleBot\/1.0","version":"14.0.3.0"}

[Dagefoerde]

Pinging @rullzer; first of all, from your point of view, is this intended? How long do you expect the refresh token to be valid?

[nextcloud-bot]

GitMate.io thinks possibly related issues are #11104 (Expire tokens hardening), #11103 ([stable14] Expire tokens hardening), #11056 (OAuth 2.0: ClientNotFoundException), #3599 (Nextcloud as OAuth 2.0 provider), and #11082 (Do not invalidate main token on OAuth).

[rullzer]

@Dagefoerde mmm yes I see it from looking at the code. I'll look into the issue. Refresh tokens actually should not expire. It think this is abug.

Regarding the refresh token only being valid once. This is expected.
Check the JSON returned. There is your new refresh token.

[Dagefoerde]

I'll look into the issue. Refresh tokens actually should not expire. It think this is abug.

Perfect, thanks.

Regarding the refresh token only being valid once. This is expected.

Noo, I know! That's not the problem here. In these two attempts the refresh token was never valid. I was just trying to say that the first time there is a token but the check fails. So of course I didn't get a new refresh token here. It's just that the second time we end up in a different check, probably because the first time did some cleanup. I was just adding that because you can debug this only once (per grant) due to the cleanup stuff ;)

[rullzer]

Ah... stupid me replying to soon. 🤦‍♂️

I'll look into this and get back to you

[rullzer]

Aaah so I actually know what is going on here. The token is indeed expired. (Which makes sense). So it gets cleaned up by the cron job. But if the token is really gone our refresh mechanism can't do anything.

Ok let me see how the logic should work here.

[rullzer]

Ah no so I did not have it correct... more digging it seems.

[rullzer]

Ok so it puzzles me a bit why this happens.

@Dagefoerde could you enable xdebug on your test system?
And apply a patch:

--- a/lib/private/Authentication/Token/PublicKeyTokenProvider.php
+++ b/lib/private/Authentication/Token/PublicKeyTokenProvider.php
@@ -128,6 +128,7 @@ class PublicKeyTokenProvider implements IProvider {
        }
 
        public function invalidateToken(string $token) {
+               $this->logger->logException(new \Exception());
                $this->mapper->invalidate($this->hashToken($token));
        }

That should log a stacktrace where that is called from.

[Dagefoerde]

Hi, thanks for digging. I added it on the test system and will check later what will happen. What do you think how much time elapses until the token is invalid? I think I'll check in bit more than an hour or tomorrow.
Either way, will that show up in nextcloud.log?

[rullzer]

It should show up there yes.

I actually don't know why the token gets removed. It should be marked as expired but not removed.

[Dagefoerde]

Maybe here, right after it has been determined to be expired?

server/apps/oauth2/lib/Controller/OauthApiController.php

Line 142 in a1ea504

$this->accessTokenMapper->delete($accessToken);

(dunno though. I haven't actually tried to figure it out yet.)

[Dagefoerde]

Refresh token wasn't valid anymore, but your additional statement wasn't logged either. Just the following (which always came up before, too, so nothing new here.).

{"reqId":"buG4XKjpYykGJDI5ZH7P","level":2,"time":"2018-10-20T22:58:24+00:00","remoteAddr":"80.137.3.25","user":"--","app":"core","method":"POST","url":"\/nextcloud\/index.php\/apps\/oauth2\/api\/v1\/token","message":"Login failed: '<snip>' (Remote IP: '80.137.3.25')","userAgent":"MoodleBot\/1.0","version":"14.0.3.0"}

[rullzer]

Yeah but it should not reach that. If that is reached the token is invalid anyway.

Mmmm strange... I would need to dig deeper. I'll try to setup a test env this evneing to debug tomorrow.

[rullzer]

AAAAH! I think I got it! I'll prepare a patch in a little moment...

[rullzer]

@Dagefoerde please tests #11964. Especially the first commit

[Dagefoerde]

Yep, seems to resolve this issue. Thanks a lot for dealing with this!