azure identity token refresh issue with msi-adapter

[abhijitkaranjkar89]

Bug Report

• import path of package in question, e.g. /sdk/azidentity
• SDK version
  github.com/Azure/azure-sdk-for-go/sdk/azcore v1.11.1
  github.com/Azure/azure-sdk-for-go/sdk/azidentity v1.5.1
  github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/resources/armresources v1.2.0
• output of go version
  go 1.22

• What happened?
  We are using the msi-adapter sidecar to use Azure ARC extension's System Assigned Managed Identity for Azure cloud communication.
  While it generally works well, we've noticed that sometimes the sdk doesn't query token on msi-adapter, leading to errors during cloud communication.

RESPONSE 401: 401 Unauthorized
ERROR CODE: ExpiredAuthenticationToken

{
"error": {
"code": "ExpiredAuthenticationToken",
"message": "The access token expiry UTC time '10/16/2024 9:52:23 PM' is earlier than current UTC time '10/16/2024 10:11:14 PM'."
}
}

To us, it seems that the SDK is using some cached value cause msi-adapter shows no logs of any token request from the SDK code.
Almost all subsequent requests failed for at least next ~30 minutes and then started working again.
Below are the logs from our service.
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 3:42:24 AM'
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 3:44:24 AM'
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 4:06:24 AM'.
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 4:28:24 AM'.
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 4:50:24 AM'.

• What did you expect or want to happen?
  Token should have been refreshed if it is expired.
• How can we reproduce it?
• Anything we should know about your environment.
  Code is running on Azure AKS.

[chlowell]

Service clients and azidentity credentials both cache access tokens, however each cache checks whether tokens have expired before using them. Can you please explain what msi-adapter is and how your application gets tokens?

[github-actions]

Hi @abhijitkaranjkar89. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

[abhijitkaranjkar89]

@chlowell
The msi-adapter in Azure Arc is a component used to facilitate communication between Azure Arc-enabled resources and Azure services using Managed Service Identity (MSI). It acts as a sidecar container that helps manage the identity and authentication process for Azure Arc extensions.

When a token for Managed Identity Credential is requested, a call is made to the IMDS endpoint to retrieve the token. In our case on the edge, the MSI adapter side car intercepts this call and returns the token by making local identity requests.

Here are more details.
https://msazure.visualstudio.com/One/_wiki/wikis/One.wiki/679872/MSI-Adapter

Is there a way to enable sdk logs to check at what time the new token was requested?

[abhijitkaranjkar89]

Moreover, the following log lines are from the error returned by the SDK;
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 3:42:24 AM'
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 3:44:24 AM'
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 4:06:24 AM'.
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 4:28:24 AM'.
The access token expiry UTC time '10/15/2024 3:40:40 AM' is earlier than current UTC time '10/15/2024 4:50:24 AM'.

so, it seems the SDK did not refresh the token before making those cloud calls.

Note: We are using NewManagedIdentityCredential

[abhijitkaranjkar89]

@chlowell @jhendrixMSFT
Any update?

[chlowell]

Is there a way to enable sdk logs to check at what time the new token was requested?

Yes. If you enable logging as described in the README, you'll get messages like "ManagedIdentityCredential.GetToken() acquired a token..." (add the timestamp in your log listener). This won't tell you whether the token was from the cache; you can determine that from network logs. If you want to inspect a token to check its expiration time, you can use a simple wrapper like

import (
    "github.com/Azure/azure-sdk-for-go/sdk/azcore"
    "github.com/Azure/azure-sdk-for-go/sdk/azcore/policy"
)

type wrapper struct{
    c azcore.TokenCredential
}

func (w *wrapper) GetToken(ctx context.Context, tro policy.TokenRequestOptions) (azcore.AccessToken, error) {
    tk, err := w.c.GetToken(ctx, tro)
    if err == nil {
        // TODO: inspect or log tk.ExpiresOn
    }
    return tk, err
}

As for what's going wrong in this case, I guess azidentity could get the wrong expiration time if msi-adapter doesn't behave exactly like IMDS. Can you share an example token response from msi-adapter (please omit the token 😆)?

[github-actions]

Hi @abhijitkaranjkar89. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.