[BUG] AccessTokenInvalid for valid tokens

[luddd3]

• I have verified that the issue occurs with the latest twilio.js release and is not marked as a known issue in the CHANGELOG.md.
• I reviewed the Common Issues and open GitHub issues and verified that this report represents a potentially new issue.
• I verified that the Quickstart application works in my environment.
• I am not sharing any Personally Identifiable Information (PII)
  or sensitive account information (API keys, credentials, etc.) when reporting this issue.

I have a problem with some clients getting AccessTokenInvalid (20101) for perfectly valid tokens. The only thing I have found is that sometimes the clients have drifting clocks. E.g. a client clock is set to 2022-08-30T09:51:41.000Z and tries to use the following token (most fields redacted):

{
  "jti": "SK...-1661853237",
  "grants": {
    "identity": "....",
    "voice": {
      "incoming": {
        "allow": true
      },
      "outgoing": {
        "application_sid": "AP..."
      }
    }
  },
  "iat": 1661853237, // 2022-08-30T09:53:57.000Z
  "exp": 1661867637, // 2022-08-30T13:53:57.000Z
  "iss": "SK....",
  "sub": "AC...."
}

According to the client clock, the access token is not yet valid. Our servers sent the token to the client approximately 2022-08-30T09:53:57.995Z

A long shot, but is there any kind of limit on the number of AccessTokens for a specific client? This client had flaky internet and I created several new tokens for it.

Software versions:

• Browser(s): Electron 10.1.6
• Operating System: Mac OS X 10.16.0
• twilio.js: 2.1.1
• Third-party libraries (e.g., Angular, React, etc.): React

[bld010]

Hi @luddd3 , Twilio Developer Educator here.

How are you updating the clients' AccessTokens when their internet is flaky?

[luddd3]

When a client reconnects, it sends a login-request to our back-end. The back-end generates a new token and calls device.updateToken() with the new token. If the device is in state 'unregistered', device.register() is called.

I have tested extensively during the day and can get AccessTokenInvalid regardless of any drifting clock. This is my minimally reproducible code:

import { Call, Device } from '@twilio/voice-sdk'

async function getToken(): Promise<string> {
  // fetch and return new valid token
}

const setupTwilio = (token): void => {
  const device = new Device(token, {
    edge: ['frankfurt', 'dublin', 'roaming'],
    logLevel: 1,
    codecPreferences: ['opus' as Call.Codec, 'pcmu' as Call.Codec],
    tokenRefreshMs: 40_000, // refresh 40 seconds before token expires, default is 10 seconds
    maxCallSignalingTimeoutMs: 25_000, // this opts in to Call reconnection instead of using only basic media reconnection
  })

  const updateToken = async () => {
    try {
      const token = await getToken()
      device.updateToken(token)
      if (device.state === 'unregistered') {
        await device.register()
      }
    } catch (err) {
      console.error(err.stack)
    }
  }

  device.on('error', function (err) {
    console.log('error', err)
    const code = err.code

    // Access token errors
    if (code >= 20101 && code <= 20160) {
      updateToken()
    }
  })

  device.on('tokenWillExpire', () => {
    updateToken()
  })

  device.on('registered', () => {
    console.log('registered!')
  })

  device.register()
}

async function main() {
  const token = await getToken()
  setupTwilio(token)
}
main()

I have tested the above code by:

1. Start it
2. Wait for 'registered'
3. Turning off my internet connection
4. Wait until several connection errors have appeared
5. Start internet connection again

The above sequence will produce AccessTokenInvalid errors even though all tokens we generate are valid for 4 hours.

[bld010]

@mhuynh5757 Any insights here?

[ostap0207]

We are experiencing the same error, after analyzing Twilio websocket signalling channel it looks like token validation and registration is done via 2 separate messages and there seems to be a race condition.

Here is how succesfull registration looks like:

register is sent after listen reply is received.

Here is when error happens:

register is sent at the same time as listen and receives an error, which we assume happens because listen hasn't validated the token yet.

[charliesantos]

Hey everyone, apologies for the late response. Can you please provide all the logs you see from the browser console, along with all the websocket messages (similar to what @ostap0207 posted, but all)?

[luddd3]

Hi @charliesantos
I have created a zip file which includes everything you will need to recreate the error. All you have to do is enter a valid access token in "main.js" and follow the steps in the readme:

twilio-bug.zip

I tried to include everything you asked for in "example" in the zip-file, but I just took screenshots of the websocket-traffic since I didn't find any easy way to save it in my current browser (Firefox).

[kamalbennani]

We are facing the exact same problem!
Any updates on this @charliesantos.

[charliesantos]

Apologies for the delay. We are looking at it and still haven't found the root cause. Please bear with us in the meantime.

[dimasikturbo]

I'm observing the same issue. When my PC goes in a suspended mode (i have 10 minutes timeout) and wakes up, there is a bunch of errors including AccessTokenInvalid in the log.

[ostap0207]

Based on my logs to me this looked like a race condition between listen and register. register must only be processed after listen has finished, as the issue doesn't happen in this case.

[charliesantos]

Hey everyone, sorry for the late response. We're able to reproduce the issue and found the root cause. However, the fix is not pretty straightforward and might require some more thoughts on how we design the ideal solution. Basically, as you guys have observed, this is a race condition between listen and register signaling messages. As a workaround in the meantime, can you please try either of the following?

1. Do not call register again if you already called register one time after initializing the device. The SDK already re-registers if necessary after signaling has reconnected. See code here https://github.com/twilio/twilio-voice.js/blob/master/lib/twilio/device.ts#L1189

OR

2. If you detect AccessTokenInvalid error after calling device.register(), can you retry? Not ideal but it should work in the meantime.

Please let me know your thoughts

[ibnsultan]

I encountered this error specifically when handling incoming calls. Based on my experience, it was related to the identity parameter used while generating the access token.

For example, consider a scenario where we request a token with the identity set as Banana

public static function get_access_token($identity)
{
	self::__initiate();

	$accessToken = new AccessToken(
		static::$sid,
		static::$apiKey,
		static::$apiSecret,
		3600,
		$identity
	);

	$voiceGrant = new VoiceGrant();
	$voiceGrant->setOutgoingApplicationSid(static::$twimlSid);
	$voiceGrant->setIncomingAllow(true);
	
	$accessToken->addGrant($voiceGrant);
	$token = $accessToken->toJWT();

	return ['token' => $token, 'identity' => $identity];
	
}

// issue token
self::get_access_token('Banana')

If an incoming call is made to the client, and the identity in the request callback does not match one of the issued identities (in this case, Banana), an AccessTokenInvalid error will be thrown.

public static function get_voice_response($contact, $identity = null)
{
    self::__initiate();

    $response = new VoiceResponse();

    if ($contact == self::$callerId) {
        // If identity does not match 'Banana', the token will be invalid
        $dial = $response->dial('');
        $dial->client($identity); 
    } else {
        if (strlen($contact) < 10) {
            return $response->say('Invalid phone number');
        }

        $dial = $response->dial('', ['callerId' => static::$callerId]);
        if (preg_match("/^[\d\+\-\(\) ]+$/", $contact)) {
            $dial->number($contact);
        } else {
            $dial->client($contact);
        }
    }

    return $response;
}