Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

eagerRefreshThresholdMillis doesn't work for JWTClient and service accounts #774

Closed
aaleksandrov opened this issue Aug 14, 2019 · 5 comments
Assignees
Labels
priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@aaleksandrov
Copy link

Environment details

  • Ubuntu 18.04:
  • Node.js 8.10:
  • npm version - none:
  • google-auth-library version: 5.1.2

Steps to reproduce

Code to reproduce:

import {JWT} from 'google-auth-library';
import Bluebird = require('bluebird');

const privateKey = '-----BEGIN PRIVATE KEY-----.........-----END PRIVATE KEY-----\n';
const email = '.....@...iam.gserviceaccount.com';

async function main() {
    let res = null;
    const oAuth2Client = new JWT(
        email,
        null,
        privateKey,
        'https://www.googleapis.com/auth/cloud-platform'
    );
    oAuth2Client.eagerRefreshThresholdMillis = 3000000;
    res = await oAuth2Client.refreshAccessToken();
    await Bluebird.delay(10000);
    console.log(res);

    res = await oAuth2Client.refreshAccessToken();
    await Bluebird.delay(10000);
    console.log(res);

    res = await oAuth2Client.refreshAccessToken();
    await Bluebird.delay(10000);
    console.log(res);

    res = await oAuth2Client.refreshAccessToken();
    await Bluebird.delay(10000);
    console.log(res);

    res = await oAuth2Client.refreshAccessToken();
    await Bluebird.delay(10000);
    console.log(res);
}

main().catch(console.error);

I added some logging to OAuth2Client . This is output:

running getRequestMetadataAsync
this.isTokenExpiring() true
running async refreshToken
{ Authorization: 'Bearer ya29.c.ElpkB6Nvn....._4ga0SM6o' }
running getRequestMetadataAsync
this.isTokenExpiring() true
running async refreshToken
{ Authorization: 'Bearer ya29.c.ElpkB6Nvn....._4ga0SM6o' }
running getRequestMetadataAsync
this.isTokenExpiring() true
running async refreshToken
{ Authorization: 'Bearer ya29.c.ElpkB6Nvn....._4ga0SM6o' }
running getRequestMetadataAsync
this.isTokenExpiring() true
running async refreshToken
{ Authorization: 'Bearer ya29.c.ElpkB6Nvn....._4ga0SM6o' }
running getRequestMetadataAsync
this.isTokenExpiring() true
running async refreshToken
{ Authorization: 'Bearer ya29.c.ElpkB6Nvn....._4ga0SM6o' }

So as I can see google-auth-library tries to refresh a token (and makes calls to Google Oauth2 API) but Google keeps returning the same access_token till it gets expired. Problem here is that eventually a few requests to GCP fail with 401 causing intermittent issues like googleapis/nodejs-common#430 and googleapis/nodejs-bigquery#473
This is log from my Bigquery issue

I added some logs in google-auth-library and what I got:

2019-08-13T23:48:03.111Z Current access token = "xxx", expires at 2019-08-13 23:49
2019-08-13T23:48:12.111Z Gooole auth library attempts refreshing a token ...
2019-08-13T23:48:91.111Z New token "xxx", expires at 2019-08-13 23:49         <---(SAME ONE, expiring in less than one second)
....
2019-08-13T23:49:14.111Z Making request to BigQuery with "xxx"
2019-08-13T23:49:89.111Z Error 401
....

Next request: 
....
2019-08-13T23:53:67.111Z Current access token = "xxx", expires at 2019-08-13 23:49
2019-08-13T23:53:99.111Z Gooole auth library attempts refreshing a token ...
2019-08-13T23:54:44.111Z New token "yyy", expires at 2019-08-14 00:54
....
2019-08-13T23:55:03.111Z Making request to BigQuery with "yyy"
2019-08-13T23:56:17.111Z Success

Is it a proper Google Oauth2 API behaviour? Can it be fixed on google-auth-library side? This issue is quite annoying and forces us make workarounds :(

@yoshi-automation yoshi-automation added triage me I really want to be triaged. 🚨 This issue needs some love. labels Aug 15, 2019
@bcoe bcoe added type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. priority: p2 Moderately-important priority. Fix may not be included in next release. needs work This is a pull request that needs a little love. and removed 🚨 This issue needs some love. triage me I really want to be triaged. labels Aug 20, 2019
@brendanw
Copy link

I am seeing intermittent 401s as well mostly when hitting androidpublisher.purchases.subscriptions.get. Requesting https://developers.google.com/android-publisher/api-ref/inappproducts/get I see intermittent 401s but much less often.

@JustinBeckwith JustinBeckwith added priority: p1 Important issue which blocks shipping the next release. Will be fixed prior to next release. priority: p2 Moderately-important priority. Fix may not be included in next release. and removed needs work This is a pull request that needs a little love. priority: p2 Moderately-important priority. Fix may not be included in next release. priority: p1 Important issue which blocks shipping the next release. Will be fixed prior to next release. labels Sep 14, 2019
@ankurverma1994
Copy link

I got the following error: Error: Request had invalid authentication credentials. Expected OAuth 2 access token when writing data to pub-sub from cloud task.
Haven't faced the same issue earlier. (Cloud task is run often and it writes data to pub-sub successfully).
I guess this PR should cover the solution: googleapis/node-gtoken#229

@bcoe
Copy link
Contributor

bcoe commented Sep 27, 2019

@aaleksandrov one small issue with your sample code, I believe I was being returned tokens that expire after 8 hours (rather than 50 minutes) so to confirm that this bug is fixed, you'll want to use a larger eager refresh setting ...

Having said this, there was a major bug with eager refresh, which your reproduction brought to our attention, please try google-auth-library@5.3.0 and see if it corrects your issues? (@ankurverma1994 likewise give it a shot).

@aaleksandrov
Copy link
Author

Looks like #794 should fix the issue. I cannot verify it immediately because the issues mostly happened in production (don't want to break production but we have some logs in place so I'll keep an eye)

@bcoe
Copy link
Contributor

bcoe commented Oct 9, 2019

@aaleksandrov 👍 please feel free to reopen this if you do continue to see issues; thanks for the bug report and great reproduction.

@bcoe bcoe closed this as completed Oct 9, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
Development

No branches or pull requests

6 participants