[BUG] tokenWillExpire listener being triggered just once

[bgalartza]

• 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.

Code to reproduce the issue:

In order to reproduce the issue at least two tokens are needed. To simplify the steps, both tokens were created just before execution the code.

• token 1 with ttl 120 second
• token 2 with ttl 240 second

token1 = ""
token2 = ""

dev = new Twilio.Device(token1, {logLevel: 1, debug: true, tokenRefreshMs: 30000 })

dev.on('tokenWillExpire', () => {
    console.log("Token update")
    dev.updateToken(token2);
});

dev.connect()

Expected behavior:

The tokenWillExpire listener should be triggered twice:

• when token1 is about to expire
• when token2 is about to expire

So:

• The "Token update" string should be printed twice in the console.
• I'm aware that the second execution of the listener would fail because by the time it's executed the token2 would be expired. In reality that should call the BE to obtain a third token, but it was done like that to simplify the code. It's not important for this demo because the code is never executed for the second time.

Actual behavior:
The listener is called just once, and the "Token update" string is printed once.

The first time the listener is called as expected:

Token update [debugger eval code:2:13]
Setting token and publishing listen

But there are no more logs after this until token2 is expired and Twilio complains about the expired AccessToken

AccessTokenExpired: AccessTokenExpired (20104): The Access Token provided to the Twilio API has expired, the expiration time specified in the token was invalid, or the expiration time specified was too far in the future

By giving a quick look to the related code I understand that the timer is only initialized when the connected event happens. So the timer is stopped after the first listener trigger, and it's not re-initialized again until a new connection happens. I might be missing something, but maybe the timeout should be initiated after the token update too?

Also, I would expect that the timer is initialized just after you init the Device object, and not when a new call is started. Because it might happen that the access-token is already expired when trying to create an outgoing call or registering for incoming ones.

Software versions:

• Browser(s): 91.9.0esr (64-bit)
• Operating System: Debian Bullseye 11
• twilio.js: 2.1.1
• Third-party libraries (e.g., Angular, React, etc.): React

[mhuynh5757]

Hi @bgalartza, we've created a ticket for the team to track internally. Thanks for bringing this one up!

[charliesantos]

@bgalartza we're seeing this behavior in our testing:

• If you provide an expired token while calling device.updateToken(token), the device object will emit an AccessTokenExpired (20104) error. Please listen to this error so you can renew your token.
• If you provide a token that is about to expire, the device still emits tokenWillExpire event. Subsequently if you provide another token that is about to expire, the device will again emit tokenWillExpire event.

[bgalartza]

Hello,
Did you try with the piece of code we provided in the issue message? We tried again and we still get a wrong behavior:

• When token1 expires the tokenWillExpire event is successfully emitted and our callback executed. We get our print ("Token updated") and a Twilio log ("Setting token and publishing listen ")
• When token2 is about to expire tokenWillExpire is not triggered and our callback is not executed.
• When token2 expires we get a AccessTokenExpired (20104) error. And the "Stream is offline " Twilio log.

Or are we missing something in the sample piece of code that we provided?

Thank you

[charliesantos]

Hi @bgalartza to understand better wether this is a bug or not, we need to know the timestamps between each step. Right before you call updateToken using token1, please log the value of the token and also log the current timestamp.
Similarly, right before you call updateToken using token2, please log the value of the token and also log the current timestamp. And right when AccessTokenExpired is emitted, please log the current timestamp. Now decode the value of token1 and token2 and let's check the expiration time. You can use a jwt decoder something like this http://calebb.net.
Once we get all the timestamps, we can get a better understanding of what's happening.

[charliesantos]

@bgalartza can you please provide the above information? Or is this not an issue anymore?

[bgalartza]

Hello:
We debugged the timestamps using the following code:

token1 = "xxx"
token2 = "yyy"

console.log(Date.now())
dev = new Twilio.Device(token1, {logLevel: 1, debug: true, tokenRefreshMs: 30000 })

dev.on('tokenWillExpire', () => {
    console.log("Token update")
    console.log(Date.now())
    dev.updateToken(token2);
});

dev.on('error', (twilioError, call) => {
 console.log('An error has occurred: ', twilioError);
  console.log(Date.now())
});

dev.connect();

And the results are:
Timestamp 1: 1683206665681
Timestamp 2 (Token update) : 1683206723369
Timestamp 3 (AccessTokenExpired error): 1683206888544
Expirations:
Token 1: 1683206753000
Token 2: 1683206888000

I would say they look OK:
Timestamp 1 < token 1 expiration
Timestamp 2 < token 2 expiration
Timestamp 3 +-= token2 expiration
(Token 2 expiration - timestamp 2 = 164631) > tokenRefreshMs

[charliesantos]

Thanks @bgalartza for the additional information.

I would say they look OK

Does this mean the behavior is what you expect and we can close this now?

[bgalartza]

Hello,
What I meant is that the timestamps are sensible for the test we were doing. The unexpected behavior is still there:
The tokenWillExpire event is only triggered just once. When token2 is about to expire the tokenWillExpire is not triggered (we don't see the "Token update" print). Then the AccessTokenExpired exception is thrown.

[Tomer-Priel]

Hi @charliesantos

Is there a fix for this issue, we see this behaviour @bgalartza described in our code as well.

Thanks

[charliesantos]

Hey everyone, sorry for the late response. We're bumping this up in priority and we'll take a look in the next few sprints.

[charliesantos]

Hey everyone, sorry for the delay in response. We are still not able to reproduce this issue even after using the code provided in this ticket. Are you still seeing this issue in the latest version of the SDK (v2.10.1)? If yes:

• Can you try generating the new token right before calling device.updateToken(token), instead of generating both at the same time? Something like

  token1 = generateToken();
  
  dev = new Twilio.Device(token1, {logLevel: 1, debug: true, tokenRefreshMs: 30000 })
  
  dev.on('tokenWillExpire', () => {
      console.log("Token update")
      token2 = generateToken();
      dev.updateToken(token2);
  });

• Can you please update to SDK v2.10.1, enable debug mode, and provide the logs?
• Is it possible for you to provide a simple test app that I can run locally? Frontend app is fine. I can fill in the token generate part on the backend.