Goth return access token expired

[Zat42]

2022-05-27 09:33:45.196 GMT Pubsub token : %Goth.Token{
    account: nil,
    expires: 1653643540, # 2022-05-27 09:25:40 GMT
    scope: nil,
    sub: nil,
    token: "<redacted>",
    type: "Bearer"
}

For some reason, Goth is returning expired access token. Could this be related to #131 ? (@aleDsz)

I am currently using :goth, "~> 1.3-rc.4", previous version seems to be fine.

[wojtekmach]

by previous version did you mean previous 1.3-rc or 1.2 or older?

[Zat42]

1.3-rc and I am pretty sure it was 1.3-rc.3, but I need to check to be sure. Anyway I never had this kind on problem before 🤔

[wojtekmach]

These things are hard to reproduce, but if you are successful, please let us know.

FWIW on my part I did set refresh_after: 5000 and observed that the token is correctly refreshed every 5s. I also wrote a script that uses the default settings and hits an API every minute for a couple of hours and yeah, sure enough the token got automatically refreshed on ~55min mark.

[Zat42]

I just did some digging in the logs and it seems that newly "generated" (retrieved) token only last for 30 minutes instead of 1 hour. It is like the "refresh token" action is not synchronized with token expiration time.

[Zat42]

I will try to completely remove my cloud run instance and build it again to see if this solve the issue, I don't know exactly why but maybe it's just the update from :refresh_before to :refresh_after that messed up some timings?

[wojtekmach]

Oh wow, ok, this is good to know. What type of :source do you use? {:refresh_token, _, _}? I see we are not setting any expiration on that source type.

[Zat42]

I use :metadata as :source.

I don't know how to explain this correctly but I think that if a token is already existing in metadata and you update Goth from 1.3-rc.3 to 1.3-rc.4, when instance restarts, it will find a token and thinks it is a fresh one, valid for an hour, although it has already live for 30mn. Does this make sense to you?

[wojtekmach]

Yeah, I'll test with metadata. Thank you so much for pointers.

[wojtekmach]

Ok, here's what's happening. When we request a token from the metadata service, we're not gonna get a new token each time. It's gonna keep returning us the same token. So we cannot do :refresh_after, we must do :refresh_before, because otherwise on a new deployment we are not able to correctly calculate for how long the token is valid.

@Zat42 thank you so much for reporting this issue and helping debug it! We'll have a new RC next week.

[Zat42]

@wojtekmach thank you for checking! I am using a short :refresh_after time until new version is released 👌

[martosaur]

Hi folks, I think there is still some issue in there. Every morning after I wake my laptop from sleep Goth.fetch gets me either a seemingly valid but expired token or this error:

iex()1> Goth.fetch(MyGoth) 
{:error,
 %RuntimeError{
   message: "unexpected status 400 from Google\n\n{\"error\":\"invalid_grant\",\"error_description\":\"Invalid JWT: Token must be a short-lived token (60 minutes) and in a reasonable timeframe. Check your iat and exp values in the JWT claim.\"}\n"
 }}

We use all default configuration with custom HTTP client {Goth, name: MyGoth, http_client: &MyGoth.HTTP.request/1} and rely on GOOGLE_APPLICATION_CREDENTIALS=path/to/credentials.json env variable for credentials. We also didn't see any issues on deployed environments.

I didn't dig too deep, but let me know if you need any additional info!

[wojtekmach]

For performance we rely on cache as much as possible, if cache is hot we assume it is valid and we schedule refreshes to keep it so. When scheduler goes to sleep, that is thrown out if the window.

i think what we could do is in Goth.fetch after grabbing the token we compare it with system time. If it has expired we’d do a GenServer call to get a fresh one. WDYT? Would you like to explire it?

[martosaur]

@wojtekmach sounds good, here's my attempt https://github.com/peburrows/goth/pull/141