failed, status code 401 and description: ExpiredToken: The token is expired

[XiaoYue2-22]

1.The application is running in on-prem Kubernetes (VMware Tanzu). Tokens are provided through the environmental variables AZURE_TENANT_ID, AZURE_CLIENT_ID, AZURE_CLIENT_SECRET.

AZURE_SDK_GO_LOGGING=all is already turned on.

2.The application runs for a while and then throws token expired error, after restart the application, it works well and the issue is unable to reproduce now. As this is production environment, we would like to confirm if this error related to SDK.

3.The SDKs that were being used are:

azidentity v1.7.0azservicebus v1.7.1

4. We have the below code for setting up the Service Bus client:

func GetAzureClient() *azservicebus.Client {
  opts := azcore.ClientOptions{}
  tokenCredential, err := azidentity.NewDefaultAzureCredential(&azidentity.DefaultAzureCredentialOptions{ClientOptions: opts})
  if err != nil {
    panic(err)
  }
  url := viper.GetViper().GetString("AZURE.SERVICEBUS_HOSTNAME")
  client, err := azservicebus.NewClient(url, tokenCredential, nil)
  if err != nil {
    panic(err)
  }
  return client
}

We then believe the code that failed was this:

receiver, err := client.NewReceiverForQueue(q.QueueName, nil)
// error handling
messages, err := receiver.ReceiveMessages(ctx, 1, nil)

5. Error:
   Answer: 2024-12-11 19:47:18.000  [Dec 11 08:47:18.000304] Authentication: ClientSecretCredential.GetToken() acquired a token for scope 'https://servicebus.azure.net//.default'
   2024-12-11 19:47:18.000  [Dec 11 08:47:18.000317] azsb.Auth: (internal-production-ssceventresponse-sscack-v1-cipa-chullora-queue) negotiate claim, token expires on 2024-12-11T09:35:16Z

2024-12-11 19:47:19.942  [Dec 11 08:47:19.942714] azsb.Auth: Failed to send/receive RPC message: rpc: failed, status code 401 and description: ExpiredToken: The token is expired. TrackingId:0871a6a2-9467-4bda-868b-ba67793ae578, SystemTracker:NoSystemTracker, Timestamp:2024-12-11T08:47:19
2024-12-11 19:47:19.970 [Dec 11 08:47:19.970211] azsb.Auth: (internal-production-ssceventresponse-sscack-v1-cipa-chullora-queue/$management) negotiate claim, failed: rpc: failed, status code 401 and description: ExpiredToken: The token is expired. TrackingId:0871a6a2-9467-4bda-868b-ba67793ae578, SystemTracker:NoSystemTracker, Timestamp:2024-12-11T08:47:19
2024-12-11 19:47:19.970  [Dec 11 08:47:19.970234] azsb.Auth: NegotiateClaimRefresh Retry attempt 0 returned non-retryable error: rpc: failed, status code 401 and description: ExpiredToken: The token is expired. TrackingId:0871a6a2-9467-4bda-868b-ba67793ae578, SystemTracker:NoSystemTracker, Timestamp:2024-12-11T08:47:19
2024-12-11 19:47:19.970  [Dec 11 08:47:19.970240] azsb.Auth: [internal-production-ssceventresponse-sscack-v1-cipa-chullora-queue/$management] fatal error, stopping token refresh loop: rpc: failed, status code 401 and description: ExpiredToken: The token is expired. TrackingId:0871a6a2-9467-4bda-868b-ba67793ae578, SystemTracker:NoSystemTracker, Timestamp:2024-12-11T08:47:19
2024-12-11 19:47:20.052  [Dec 11 08:47:20.052522] azsb.Auth: negotiating claim for audience amqps://integ-shared-sbus-bslau-prod-aes.servicebus.windows.net/internal-production-ssceventresponse-sscack-v1-cipa-chullora-queue/$management with token type jwt and expiry of 1733906417

amqps://integ-shared-sbus-bslau-prod-aes.servicebus.windows.net/internal-production-ssceventresponse-sscack-v1-cipa-chullora-queue/$management with token type jwt and expiry of 1733906417

[XiaoYue2-22]

is it possible to print the token to troubleshooting? If so how to print this?

[XiaoYue2-22]

Hello team, any update?

[richardpark-msft]

@XiaoYue2-22, sorry about that delay. I was actually looking into this some more as it's definitely an odd error. I'm adding @chlowell, as well, as they own the authentication part of the SDK overall.

One question we had was about the timestamps in the log snippet you sent us, since we're dealing with expirations. What is the timezone in this timestamp (2024-12-11 19:47:19.942) in the log snippet below:

2024-12-11 19:47:19.942  [Dec 11 08:47:19.942714] azsb.Auth: Failed to send/receive RPC message: rpc: failed, status code 401 and description: ExpiredToken: The token is expired. TrackingId:0871a6a2-9467-4bda-868b-ba67793ae578, SystemTracker:NoSystemTracker, Timestamp:2024-12-11T08:47:19

[XiaoYue2-22]

Hello @richardpark-msft thanks for your reply. 2024-12-11 19:47:19.942 is local time which is UTC+11 and Dec 11 08:47:19.942714 is UTC time.
How to debug this issue further? Is it possible to print the token to troubleshooting? If so how to print this?

[richardpark-msft]

@chlowell, any ideas with @XiaoYue2-22's question? Are there better ways to troubleshoot this?

[chlowell]

Editing the logs for clarity, I get this (all times UTC):

1. Dec 11 08:47:18.00030 ClientSecretCredential.GetToken() acquired a token
2. 08:47:18.00031 azsb.Auth: token expires on 2024-12-11T09:35:16Z
   • we're talking about an Entra access token here. Reported expiration time implies the token came from the cache and that the credential correctly judged the token hadn't expired
3. 08:47:19.94271 azsb.Auth: Failed to send/receive RPC message: ExpiredToken... Timestamp:2024-12-11T08:47:19
   • this timestamp appears to come from Service Bus. If so, we can rule out clock skew
4. 08:47:20.05252 azsb.Auth: negotiating claim for audience... token type jwt and expiry of 1733906417
   • 1733906417 = 2024-12-11T08:40:17, which is indeed in the past
   • this message comes from

     azure-sdk-for-go/sdk/messaging/azservicebus/internal/cbs.go

     Line 61 in bca23b5

     azlog.Writef(exported.EventAuth, "negotiating claim for audience %s with token type %s and expiry of %s", audience, token.TokenType, token.Expiry)

I see no evidence of an azidentity bug because the logs indicate ClientSecretCredential.GetToken() returned an access token valid for another 47 minutes. The logged timestamps imply no meaningful clock skew.

So I think the question is, what's the expired token mentioned in messages 3 and 4, and where did it come from? Is that a different token, or is the client somehow misreporting or misrecording the Entra access token's expiration time?