Access token expiration race condition

[slayybelle]

Describe the bug
When using an access token near its time of expiration, ltijs will throw this error HTTPError: Response code 401 (Unauthorized)

Happens intermittently, but due to a recent addition of a cron job which ran hourly I was finally able to track this down.

Happens with calls to getLineItemById, getLineItems; I suppose anything that calls platform.platformAccessToken

Expected behavior
Refresh the access token; perhaps add an almost-empty flag to give some extra time to handle this case

Provider logs
See the commented section towards the bottom where I added code to track this condition where the token is within 10s of expiring.

This is from Platform.js:

async platformAccessToken(scopes) {
    const result = await (0, _classPrivateFieldGet2.default)(this, _Database).Get((0, _classPrivateFieldGet2.default)(this, _ENCRYPTIONKEY2), 'accesstoken', {
      platformUrl: (0, _classPrivateFieldGet2.default)(this, _platformUrl),
      clientId: (0, _classPrivateFieldGet2.default)(this, _clientId),
      scopes: scopes
    });
    let token;

    if (!result || (Date.now() - result[0].createdAt) / 1000 > result[0].token.expires_in) {
      provPlatformDebug('Valid access_token for ' + (0, _classPrivateFieldGet2.default)(this, _platformUrl) + ' not found');
      provPlatformDebug('Attempting to generate new access_token for ' + (0, _classPrivateFieldGet2.default)(this, _platformUrl));
      provPlatformDebug('With scopes: ' + scopes);
      token = await Auth.getAccessToken(scopes, this, (0, _classPrivateFieldGet2.default)(this, _ENCRYPTIONKEY2), (0, _classPrivateFieldGet2.default)(this, _Database));
    } else {
      provPlatformDebug('Access_token found');
      token = result[0].token;
  //=========================== I ADDED THIS CODE TO TEST:
    if (!result || (Date.now() - result[0].createdAt) / 1000 > result[0].token.expires_in - 10) {
            console.log("LTIJS: hit edge condition, token almost expired", result[0], Date.now() - result[0].createdAt);
    }
    }

here is what my logs looks like when a getMembers request fails. Note the time computed is 3599933 which is so close to the 3600000ms (expiration time), but is still treated as not-expired

LTIJS: hit edge condition, token almost expired {
  token: {
    access_token: '75aee939de83210f089d7259a728cf65',
    token_type: 'Bearer',
    expires_in: 3600,
    scope: 'https://purl.imsglobal.org/spec/lti-nrps/scope/contextmembership.readonly'
  },
  createdAt: 1677285068000
} 3599933
[2023-02-25T01:31:08.275Z] ERROR: xxxxx/service:lti:roster/2422158 on ip-172-16-0-249: ERROR retrieving roster for YYYYYY (err.code=ERR_NON_2XX_3XX_RESPONSE)
    HTTPError: Response code 401 (Unauthorized)
        at Request.<anonymous> (/usr/local/xxxxx/node_modules/got/dist/source/as-promise/index.js:118:42)
        at processTicksAndRejections (node:internal/process/task_queues:96:5)

Screenshots
If applicable, add screenshots to help explain your problem.

Ltijs version

• Version 5.8.9

NodeJS version

• v16.19.0

Platform used

• Canvas

[Cvmcosta]

Hello @slayybelle very interesting find! Thank you. I am guessing the more straight forward solution for this is to not test the expiration time exactly but instead check if it's expiring soon. I will add this to this to my list of improvements and will get it done as soon as i can.