What steps will reproduce the problem?
1. authenticate and acquire access token which expires_in 3600 seconds
2. poll oauth endpoint indefinitely every 60 seconds
3. on the 60th poll, the query will fail, returning the upstream 401 authError
(or whatever it returns)
4. the next poll (60 seconds later) will succeed
For a concrete (though complex) example, http://github.com/asjoyner/fuse_gdrive
exhibits this behavior.
What is the expected output? What do you see instead?
On the 60th poll, when oauth.Transport.RoundTrip checks for "if t.Expired()",
it should notice the token has expired, and trigger Refresh() before making the
requested HTTP request.
https://code.google.com/p/goauth2/source/browse/oauth/oauth.go#318
What version of the product are you using? On what operating system?
80:afe77d958c70 cloned from this repo, on both OS X 10.9.5 and Debian Linux 7.7
(wheezy, latest stable)
Please provide any additional information below.
I believe the root cause here is a subtle timing problem, where Go's high
resolution timers are being a bit too precise. Consider a select loop, driven
by a time.Ticker, making a request every 60 seconds:
T0: timer ticks, Refresh() requests new AccessToken, server calculates expiry
in 3600 seconds at T3600
T0.150: receive access token with expiry_in 3600, calculate Expiry at T3600.150
T60: timer ticks, make request, it's all roses
T120: timer ticks, make request, it's all roses
...
T3600: timer ticks, getAccessToken() checks Expired(), it's got another 150ms
till Expiry... but when the request gets to the server it disagrees, and the
request is rejected.
The combination of a 1 minute poll interval, HTTP request and response latency,
expire_in only have 1 second resolution, and expiry being calculated by the
client results in my code hits this *every* Refresh() cycle. If I pad the
Expiry by even 1 second, the problem disappears.
I propose that latency might be more than 1 second in some cases, and in the
worst case clock drift might also contribute over an hour. Depending on how
the server stores the expiry, plausibly with only 1 second resolution, it might
actually record one second earlier than we do when calculating the expiration
locally. I believe the right choice is to pad the Expiry by a few seconds. I
will concede in advance that "a few seconds" is a hand-wavy answer, but hope
you too will acknowledge that timing across the internet can be unpredictable.
I've attached a patch (6 delta lines) which fixes the problem, by causing the
ticket to expire 5 seconds earlier. It also does a minor sanity check to
ensure the access token isn't made invalid by the grace period (eg. it's valid
for at least 5 seconds), and updates oauth_test.go to account for that value.
I'm in no way married to the 5 second value, it just felt about right to me.
It didn't feel important enough to expose it as a tunable value, but if you'd
like I'd be happy to submit a follow-on patch to expose it via the Config.
Original issue reported on code.google.com by asjoy...@joyner.ws on 21 Dec 2014 at 1:00
Original issue reported on code.google.com by
asjoy...@joyner.ws
on 21 Dec 2014 at 1:00Attachments: