azure identity token refresh issue with msi-adapter

abhijitkaranjkar89 commented 5 days ago

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 commented 5 days ago

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[bot] commented 5 days ago

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 commented 5 days ago

@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 commented 4 days ago

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 commented 12 hours ago

@chlowell @jhendrixMSFT Any update?

chlowell commented 11 hours ago

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[bot] commented 11 hours ago

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.

Azure / azure-sdk-for-go