Hydra: AccessToken expired for no reason

[matteosuppo]

Ok, this is complex.

In short when I use a token it tells me that it's already expired, even if I got it only moments after.

I get the token with:

    var redirectUri = encodeURIComponent("http://localhost:3000");
    location.href = "http://localhost:4444/oauth2/auth?client_id=test&response_type=token&nonce=12345679&state=statestate&scope=core&redirect_uri="+redirectUri

with the implicit flow, so I receive it in the hash

Then I make a call to warden to check if the token is valid:

private := ladon.Request{
    Resource: "arduino:user:" + id,
    Action:   "read.private",
}
allowed, err := hydra.Warden.TokenAllowed(context.Background(), token, &private, "core")

where the token is for example bearer eBBQtJe0piBksKCH_aZjgCrWRv5o_OnE-ZfK7JPgLJk.xboOPgdccrRb9LhJFxEH7vk5IX9C77YOQoEym_1_79o

I delved a bit in the code and discovered that here: https://github.com/ory-am/fosite/blob/master/handler/oauth2/strategy_hmacsha.go#L33

r.GetRequestedAt() ====>  2016-08-12 15:10:52.485 +0000 +00:00

(which is odd since today is 2016-08-16)

and here:
https://github.com/ory-am/fosite/blob/master/handler/oauth2/strategy_hmacsha_session.go#L21

s.AccessTokenExpiry ====>  0001-01-01 00:00:00 +0000 UTC

I'm not sure what's going on, if there's a bug or if I'm doing something wrong-

[faxal]

I've had this "premature expiration" issue too. I can't reproduce at the moment. I'll report with more info if it happens again.

[aeneasr]

Could it be linked to a broken system clock?

s.AccessTokenExpiry ====> 0001-01-01 00:00:00 +0000 UTC

This is ok because hydra is always using the default value so this is supposed to be "nil".

Whats the iat value?

[matteosuppo]

I don't think it's a system clock issue, because the logs have the correct date:

2016/08/16 10:48:14 2016-08-12 15:10:52.485 +0000 +00:00 1h0m0s

for log.Println(r.GetRequestedAt(), h.AccessTokenLifespan)

How can I inspect the iat value?

[aeneasr]

for log.Println(r.GetRequestedAt(), h.AccessTokenLifespan)

How can I inspect the iat value?

That's the iat (issued at) value :)

Is this maybe a token that got refreshed or is it a fresh one?

Also, what does running date in the shell of the server where hydra is running give you?

[matteosuppo]

I'm getting it with the implicit flow, so it shouldn't be a refreshed token

[aeneasr]

Ok, does the behaviour occur only with implicit tokens?

[matteosuppo]

I'm going to check

[matteosuppo]

Yes, sounds like it occur only with implicit tokens

[aeneasr]

when you receive the implicit access token in the callback, what is the value of expires_in?

[matteosuppo]

3600

[matteosuppo]

Ok, could it be because the nonce in the request was already been used on 2016-08-12 ?

[aeneasr]

yes, that's a possibility! i will check that asap

[aeneasr]

hm the nonce is only for the openid connect session, it shouldn't have an impact on the access token. does it work when you use another nonce?

[aeneasr]

@matteosuppo can we take this to the gitter chat channel?

[aeneasr]

@matteosuppo any chance you found the root cause of this issue? the problem is that it's almost impossible to write tests for the implicit flow using golang, as hashbangs are not sent to the server. to get tests working, there would need to be some sort of javascript that posts a form or similar jazz...

[matteosuppo]

I use this to get the token:

function login() {
    var redirectUri = encodeURIComponent("http://localhost:3000");
    location.href = "http://localhost:4444/oauth2/auth?client_id=test&response_type=token&nonce=9871233&state=statestate&scopes=core&redirect_uri="+redirectUri
}

function GetURLParameter(location, sParam) {
    var sPageURL = location.hash.substring(1);
    var sURLVariables = sPageURL.split('&');
    for (var i = 0; i < sURLVariables.length; i++) {
        var sParameterName = sURLVariables[i].split('=');
        if (sParameterName[0] == sParam) {
            return sParameterName[1];
        }
    }
}

token = GetURLParameter(window.location, "access_token");

But it can work only on the browser. I can try to spin up some automated tests using https://karma-runner.github.io/1.0/index.html

[matteosuppo]

Also this problem happens when I restart the hydra service. My gut tells me it has something to do with the way tokens are loaded at startup.

[faxal]

@matteosuppo yes! it's due to coldStart in fosite storage layer, recent tokens get overridden with old ones. See #207

[aeneasr]

supserseded by #207