azure-sdk-for-cpp icon indicating copy to clipboard operation
azure-sdk-for-cpp copied to clipboard

Published 20 hours ago • verified publisher icon Azure

ManagedIdentityCredential does not fail fast which results in user experience of the DAC to be degraded since it is not at the end

Open ahsonkhan opened this issue 2 years ago • 6 comments

Since ManagedIdentityCredential is no longer at the end of the chain of credentials, if it is not setup correctly and is guaranteed to fail due to a setup issue, it takes a long time before the DefaultAzureCredential moves to the next credential to try, which might have a better chance succeeding (i.e. AzureCliCredential).

This applies to the imds credential, within the set of ManagedIdentityCredential.

cc @antkmsft, @scottaddie

ahsonkhan avatar Sep 13 '23 23:09 ahsonkhan

Just listing potentional options, other than removing retries, reducing HTTP request timeout, adding support to ping an IP address, could be to drop IMDS when it is a part of a chained credential.

antkmsft avatar Sep 14 '23 22:09 antkmsft

2 optimizations are missing from the current C++ implementation.

  1. On subsequent instantiations of DAC, we go directly to the known successful credential
  2. 1-second timeout on IMDS

joshfree avatar Sep 20 '23 20:09 joshfree

Current timings - it still may take up to 90 seconds to get the token from AzureCliCredential via DefaultAzureCredential - and while this is the case, I would not use it in our samples (#5133).

I took this program:

#include <azure/core/diagnostics/logger.hpp>
#include <azure/core/internal/environment.hpp>
#include <azure/identity/default_azure_credential.hpp>

#include <chrono>
#include <iostream>
#include <memory>

int main()
{
  // Uncomment the code line below if you want no logging.
  // Otherwise, make sure that you have AZURE_LOG_LEVEL=verbose set in the environment.
  //Azure::Core::Diagnostics::Logger::SetListener(nullptr);

  // Unset all the variables that other credentials read from, to make sure DefaultAzureCredential
  // falls into AzureCliCredential.
  Azure::Core::_internal::Environment::SetVariable("AZURE_AUTHORITY_HOST", "");
  Azure::Core::_internal::Environment::SetVariable("AZURE_CLIENT_CERTIFICATE_PATH", "");
  Azure::Core::_internal::Environment::SetVariable("AZURE_CLIENT_ID", "");
  Azure::Core::_internal::Environment::SetVariable("AZURE_CLIENT_SECRET", "");
  Azure::Core::_internal::Environment::SetVariable("AZURE_FEDERATED_TOKEN_FILE", "");
  Azure::Core::_internal::Environment::SetVariable("AZURE_TENANT_ID", "");
  Azure::Core::_internal::Environment::SetVariable("IDENTITY_ENDPOINT", "");
  Azure::Core::_internal::Environment::SetVariable("IDENTITY_HEADER", "");
  Azure::Core::_internal::Environment::SetVariable("IDENTITY_SERVER_THUMBPRINT", "");
  Azure::Core::_internal::Environment::SetVariable("IMDS_ENDPOINT", "");
  Azure::Core::_internal::Environment::SetVariable("MSI_ENDPOINT", "");
  Azure::Core::_internal::Environment::SetVariable("MSI_SECRET", "");

  const auto cred = std::make_shared<Azure::Identity::DefaultAzureCredential>();
  try
  {
    Azure::Core::Credentials::TokenRequestContext trc;
    trc.Scopes.push_back("https://vault.azure.net/.default");
    auto const before = std::chrono::steady_clock::now();
    static_cast<void>(cred->GetToken(trc, Azure::Core::Context::ApplicationContext));
    auto const after = std::chrono::steady_clock::now();
    std::cout << "\n\n-=-=-= Time: "
              << std::chrono::duration_cast<std::chrono::seconds>(after - before).count()
              << " seconds. =-=-=-\n";
  }
  catch (std::exception const& ex)
  {
    std::cout << "\n\n-=-=-= Exception thrown: =-=-=-\n"
              << ex.what() << "\n-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-\n";
  }
}

Before the change to put AzureCliCredential past the ManagedIdentityCredential (the latest released GA version as of today, 1.5.1 from July 6th):

[2023-11-10T05:46:16.4215790Z] DEBUG : Identity: Creating DefaultAzureCredential which combines mutiple parameterless credentials into a single one.
DefaultAzureCredential is only recommended for the early stages of development, and not for usage in production environment.
Once the developer focuses on the Credentials and Authentication aspects of their application, DefaultAzureCredential needs to be replaced with the credential that is the better fit for the application.
[2023-11-10T05:46:16.4223744Z] WARN  : Identity: EnvironmentCredential was not initialized with underlying credential.
[2023-11-10T05:46:16.4229198Z] DEBUG : Identity: EnvironmentCredential: Both 'AZURE_TENANT_ID' and 'AZURE_CLIENT_ID', and at least one of 'AZURE_CLIENT_SECRET', 'AZURE_CLIENT_CERTIFICATE_PATH' needs to be set. Additionally, 'AZURE_AUTHORITY_HOST' could be set to override the default authority host. Currently:
 * 'AZURE_TENANT_ID' is NOT set
 * 'AZURE_CLIENT_ID' is NOT set
 * 'AZURE_CLIENT_SECRET' is NOT set
 * 'AZURE_CLIENT_CERTIFICATE_PATH' is NOT set
 * 'AZURE_AUTHORITY_HOST' is NOT set
[2023-11-10T05:46:16.4236145Z] INFO  : Identity: AzureCliCredential created.
Successful creation does not guarantee further successful token retrieval.
[2023-11-10T05:46:16.4243273Z] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2019 source.
[2023-11-10T05:46:16.4246355Z] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2017 source.
[2023-11-10T05:46:16.4249175Z] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Cloud Shell source.
[2023-11-10T05:46:16.4251736Z] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Azure Arc source.
[2023-11-10T05:46:16.4254313Z] INFO  : Identity: ManagedIdentityCredential will be created with Azure Instance Metadata Service source.
Successful creation does not guarantee further successful token retrieval.
[2023-11-10T05:46:16.4415215Z] INFO  : Identity: DefaultAzureCredential: Created with the following credentials: EnvironmentCredential, AzureCliCredential, ManagedIdentityCredential.
[2023-11-10T05:46:16.4421505Z] WARN  : Identity: EnvironmentCredential authentication unavailable. See earlier EnvironmentCredential log messages for details.
[2023-11-10T05:46:16.4455210Z] DEBUG : Identity: DefaultAzureCredential: Failed to get token from EnvironmentCredential: EnvironmentCredential authentication unavailable. Environment variables are not fully configured.
[2023-11-10T05:46:19.7327602Z] INFO  : Identity: DefaultAzureCredential: Successfully got token from AzureCliCredential.


-=-=-= Time: 3 seconds. =-=-=-

C:\src\azure-sdk-for-cpp\out\build\x64-static-debug-perftests\sdk\identity\azure-identity\samples\default_azure_credential_sample.exe (process 44832) exited with code 0.
To automatically close the console when debugging stops, enable Tools->Options->Debugging->Automatically close the console when debugging stops.
Press any key to close this window . . .

^^^^^^^^^^^^^^^^^^^^^ I ran it without the debugger attached, and it took 1 second - both with logging enabled and disabled.

After the change to put AzureCliCredential after the ManagedIdentityCredential (starting 1.6.0-beta.2) - 92 seconds:

[2023-11-10T04:57:15.7754302Z T: de8] DEBUG : Identity: Creating DefaultAzureCredential which combines mutiple parameterless credentials into a single one.
DefaultAzureCredential is only recommended for the early stages of development, and not for usage in production environment.
Once the developer focuses on the Credentials and Authentication aspects of their application, DefaultAzureCredential needs to be replaced with the credential that is the better fit for the application.
[2023-11-10T04:57:15.7760960Z T: de8] WARN  : Identity: EnvironmentCredential was not initialized with underlying credential.
[2023-11-10T04:57:15.7765478Z T: de8] DEBUG : Identity: EnvironmentCredential: Both 'AZURE_TENANT_ID' and 'AZURE_CLIENT_ID', and at least one of 'AZURE_CLIENT_SECRET', 'AZURE_CLIENT_CERTIFICATE_PATH' needs to be set. Additionally, 'AZURE_AUTHORITY_HOST' could be set to override the default authority host. Currently:
 * 'AZURE_TENANT_ID' is NOT set
 * 'AZURE_CLIENT_ID' is NOT set
 * 'AZURE_CLIENT_SECRET' is NOT set
 * 'AZURE_CLIENT_CERTIFICATE_PATH' is NOT set
 * 'AZURE_AUTHORITY_HOST' is NOT set
[2023-11-10T04:57:15.7769913Z T: de8] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2019 source.
[2023-11-10T04:57:15.7772761Z T: de8] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2017 source.
[2023-11-10T04:57:15.7775543Z T: de8] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Cloud Shell source.
[2023-11-10T04:57:15.7779169Z T: de8] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Azure Arc source.
[2023-11-10T04:57:15.7782323Z T: de8] INFO  : Identity: ManagedIdentityCredential will be created with Azure Instance Metadata Service source.
Successful creation does not guarantee further successful token retrieval.
[2023-11-10T04:57:15.7915235Z T: de8] INFO  : Identity: AzureCliCredential created.
Successful creation does not guarantee further successful token retrieval.
[2023-11-10T04:57:15.7920916Z T: de8] INFO  : Identity: DefaultAzureCredential: Created with the following credentials: EnvironmentCredential, WorkloadIdentityCredential, ManagedIdentityCredential, AzureCliCredential.
[2023-11-10T04:57:15.7923573Z T: de8] WARN  : Identity: EnvironmentCredential authentication unavailable. See earlier EnvironmentCredential log messages for details.
[2023-11-10T04:57:15.8137259Z T: de8] DEBUG : Identity: DefaultAzureCredential: Failed to get token from EnvironmentCredential: EnvironmentCredential authentication unavailable. Environment variables are not fully configured.
[2023-11-10T04:57:15.8149043Z T: de8] DEBUG : Identity: DefaultAzureCredential: Failed to get token from WorkloadIdentityCredential: WorkloadIdentityCredential authentication unavailable. Environment variables are not fully configured.
[2023-11-10T04:57:15.8180667Z T: de8] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : 4f38a4d4-5885-4e61-8785-a079164e9ca9
[2023-11-10T04:57:15.8320146Z T: 80fc] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T04:57:15.8323510Z T: 80fc] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T04:57:15.8337171Z T: 80fc] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T04:57:36.8682879Z T: 80fc] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T04:57:36.8718612Z T: 80fc] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T04:57:36.8825017Z T: de8] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T04:57:36.8847740Z T: de8] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T04:57:36.8870280Z T: de8] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T04:57:36.8892456Z T: de8] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T04:57:36.8917948Z T: de8] INFO  : HTTP Retry attempt #1 will be made in 640ms.
[2023-11-10T04:57:37.5468817Z T: de8] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : 4f38a4d4-5885-4e61-8785-a079164e9ca9
[2023-11-10T04:57:37.5497010Z T: 82c8] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T04:57:37.5515521Z T: 82c8] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T04:57:37.5527899Z T: 82c8] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T04:57:58.6030933Z T: 82c8] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T04:57:58.6061336Z T: 82c8] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T04:57:58.6164952Z T: de8] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T04:57:58.6188388Z T: de8] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T04:57:58.6212438Z T: de8] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T04:57:58.6236175Z T: de8] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T04:57:58.6254962Z T: de8] INFO  : HTTP Retry attempt #2 will be made in 1730ms.
[2023-11-10T04:58:00.3586562Z T: de8] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : 4f38a4d4-5885-4e61-8785-a079164e9ca9
[2023-11-10T04:58:00.3627486Z T: 80fc] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T04:58:00.3655254Z T: 80fc] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T04:58:00.3682715Z T: 80fc] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T04:58:21.3981242Z T: 3cfc] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T04:58:21.4012302Z T: 3cfc] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T04:58:21.4073332Z T: de8] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T04:58:21.4086229Z T: de8] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T04:58:21.4093600Z T: de8] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T04:58:21.4096299Z T: de8] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T04:58:21.4098915Z T: de8] INFO  : HTTP Retry attempt #3 will be made in 2869ms.
[2023-11-10T04:58:24.2856145Z T: de8] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : 4f38a4d4-5885-4e61-8785-a079164e9ca9
[2023-11-10T04:58:24.2894257Z T: 80fc] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T04:58:24.2916038Z T: 80fc] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T04:58:24.2938460Z T: 80fc] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T04:58:45.3502888Z T: 80fc] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T04:58:45.3532694Z T: 80fc] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T04:58:45.3640447Z T: de8] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T04:58:45.3660890Z T: de8] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T04:58:45.3666612Z T: de8] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T04:58:45.3672036Z T: de8] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T04:58:45.3711584Z T: de8] DEBUG : Identity: DefaultAzureCredential: Failed to get token from ManagedIdentityCredential: GetToken(): Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T04:58:48.1096027Z T: de8] INFO  : Identity: DefaultAzureCredential: Successfully got token from AzureCliCredential.


-=-=-= Time: 92 seconds. =-=-=-

C:\src\azure-sdk-for-cpp\out\build\x64-static-debug-perftests\sdk\identity\azure-identity\samples\default_azure_credential_sample.exe (process 29300) exited with code 0.
To automatically close the console when debugging stops, enable Tools->Options->Debugging->Automatically close the console when debugging stops.
Press any key to close this window . . .

After the change to reuse the last successful credential (#5142) - 90 seconds:

[2023-11-10T05:12:21.4043040Z T: 9f04] DEBUG : Identity: Creating DefaultAzureCredential which combines mutiple parameterless credentials into a single one.
DefaultAzureCredential is only recommended for the early stages of development, and not for usage in production environment.
Once the developer focuses on the Credentials and Authentication aspects of their application, DefaultAzureCredential needs to be replaced with the credential that is the better fit for the application.
[2023-11-10T05:12:21.4051425Z T: 9f04] WARN  : Identity: EnvironmentCredential was not initialized with underlying credential.
[2023-11-10T05:12:21.4057464Z T: 9f04] DEBUG : Identity: EnvironmentCredential: Both 'AZURE_TENANT_ID' and 'AZURE_CLIENT_ID', and at least one of 'AZURE_CLIENT_SECRET', 'AZURE_CLIENT_CERTIFICATE_PATH' needs to be set. Additionally, 'AZURE_AUTHORITY_HOST' could be set to override the default authority host. Currently:
 * 'AZURE_TENANT_ID' is NOT set
 * 'AZURE_CLIENT_ID' is NOT set
 * 'AZURE_CLIENT_SECRET' is NOT set
 * 'AZURE_CLIENT_CERTIFICATE_PATH' is NOT set
 * 'AZURE_AUTHORITY_HOST' is NOT set
[2023-11-10T05:12:21.4063027Z T: 9f04] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2019 source.
[2023-11-10T05:12:21.4069125Z T: 9f04] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2017 source.
[2023-11-10T05:12:21.4073693Z T: 9f04] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Cloud Shell source.
[2023-11-10T05:12:21.4077606Z T: 9f04] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Azure Arc source.
[2023-11-10T05:12:21.4081397Z T: 9f04] INFO  : Identity: ManagedIdentityCredential will be created with Azure Instance Metadata Service source.
Successful creation does not guarantee further successful token retrieval.
[2023-11-10T05:12:21.4265854Z T: 9f04] INFO  : Identity: AzureCliCredential created.
Successful creation does not guarantee further successful token retrieval.
[2023-11-10T05:12:21.4274437Z T: 9f04] INFO  : Identity: DefaultAzureCredential: Created with the following credentials: EnvironmentCredential, WorkloadIdentityCredential, ManagedIdentityCredential, AzureCliCredential.
[2023-11-10T05:12:21.4279926Z T: 9f04] WARN  : Identity: EnvironmentCredential authentication unavailable. See earlier EnvironmentCredential log messages for details.
[2023-11-10T05:12:21.4316415Z T: 9f04] DEBUG : Identity: DefaultAzureCredential: Failed to get token from EnvironmentCredential: EnvironmentCredential authentication unavailable. Environment variables are not fully configured.
[2023-11-10T05:12:21.4377565Z T: 9f04] DEBUG : Identity: DefaultAzureCredential: Failed to get token from WorkloadIdentityCredential: WorkloadIdentityCredential authentication unavailable. Environment variables are not fully configured.
[2023-11-10T05:12:21.4429807Z T: 9f04] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : d5e9ed54-836e-4d0b-ab31-8041439cf8fe
[2023-11-10T05:12:21.4596865Z T: 3648] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T05:12:21.4602192Z T: 3648] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T05:12:21.4618759Z T: 3648] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T05:12:42.4912392Z T: 3648] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T05:12:42.4929832Z T: 3648] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T05:12:42.4975298Z T: 9f04] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T05:12:42.4979382Z T: 9f04] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T05:12:42.4982656Z T: 9f04] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T05:12:42.4986086Z T: 9f04] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T05:12:42.4989428Z T: 9f04] INFO  : HTTP Retry attempt #1 will be made in 640ms.
[2023-11-10T05:12:43.1549760Z T: 9f04] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : d5e9ed54-836e-4d0b-ab31-8041439cf8fe
[2023-11-10T05:12:43.1593723Z T: 8c60] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T05:12:43.1620699Z T: 8c60] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T05:12:43.1652143Z T: 8c60] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T05:13:04.2233818Z T: 8c60] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T05:13:04.2264475Z T: 8c60] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T05:13:04.2321716Z T: 9f04] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T05:13:04.2334869Z T: 9f04] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T05:13:04.2339598Z T: 9f04] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T05:13:04.2342121Z T: 9f04] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T05:13:04.2344872Z T: 9f04] INFO  : HTTP Retry attempt #2 will be made in 1730ms.
[2023-11-10T05:13:05.9724339Z T: 9f04] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : d5e9ed54-836e-4d0b-ab31-8041439cf8fe
[2023-11-10T05:13:05.9767305Z T: 8c60] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T05:13:05.9796144Z T: 8c60] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T05:13:05.9816879Z T: 8c60] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T05:13:27.0147391Z T: 8c60] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T05:13:27.0166462Z T: 8c60] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T05:13:27.0251821Z T: 9f04] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T05:13:27.0272649Z T: 9f04] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T05:13:27.0282993Z T: 9f04] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T05:13:27.0293529Z T: 9f04] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T05:13:27.0311807Z T: 9f04] INFO  : HTTP Retry attempt #3 will be made in 2869ms.
[2023-11-10T05:13:29.9085654Z T: 9f04] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
metadata : REDACTED
user-agent : azsdk-cpp-identity/1.6.0-beta.4 (Windows 10 Enterprise 6.3 22621 22621.1.amd64fre.ni_release.220506-1250)
x-ms-client-request-id : d5e9ed54-836e-4d0b-ab31-8041439cf8fe
[2023-11-10T05:13:29.9121618Z T: 3648] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
[2023-11-10T05:13:29.9145972Z T: 3648] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
[2023-11-10T05:13:29.9177282Z T: 3648] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
[2023-11-10T05:13:50.9498287Z T: 3648] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
[2023-11-10T05:13:50.9514760Z T: 3648] ERROR : Request error.  Error Code: 12002: The operation timed out
. 5
[2023-11-10T05:13:50.9596442Z T: 9f04] DEBUG : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
[2023-11-10T05:13:50.9607230Z T: 9f04] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
[2023-11-10T05:13:50.9618058Z T: 9f04] DEBUG : Closing handle; completing outstanding Close request
[2023-11-10T05:13:50.9629644Z T: 9f04] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T05:13:50.9746582Z T: 9f04] DEBUG : Identity: DefaultAzureCredential: Failed to get token from ManagedIdentityCredential: GetToken(): Error while waiting for a send to complete. Error Code: 12002: The operation timed out
.
[2023-11-10T05:13:52.2606045Z T: 9f04] INFO  : Identity: DefaultAzureCredential: Successfully got token from AzureCliCredential. Reuse this credential for subsequent calls.
[2023-11-10T05:13:52.2654339Z T: 9f04] DEBUG : Identity: DefaultAzureCredential: Save this credential at index 3 for subsequent calls.


-=-=-= Time: 90 seconds. =-=-=-

C:\src\azure-sdk-for-cpp\out\build\x64-static-debug-perftests\sdk\identity\azure-identity\samples\default_azure_credential_sample.exe (process 32588) exited with code 0.
To automatically close the console when debugging stops, enable Tools->Options->Debugging->Automatically close the console when debugging stops.
Press any key to close this window . . .

After the change to reuse the last successful credential, logging disabled - the same ~90 seconds (92 actually), but for these 92 seconds, you stare into the darkness:

-=-=-= Time: 92 seconds. =-=-=-

C:\src\azure-sdk-for-cpp\out\build\x64-static-debug-perftests\sdk\identity\azure-identity\samples\default_azure_credential_sample.exe (process 16988) exited with code 0.
To automatically close the console when debugging stops, enable Tools->Options->Debugging->Automatically close the console when debugging stops.
Press any key to close this window . . .

antkmsft avatar Nov 10 '23 05:11 antkmsft

To summarize: Before reordering, a customer could start a sample, and it would take 3 seconds to authenticate (and when I ran with logging but no debugger attached, it took 1 second). Currently, it is 90+ seconds with debugger attached. Logging has no impact.

If we intend to GA the new credential order in the chain (when AzureCliCredential comes after ManagedIdentityCredential), we need another fix to be made, when the ManagedIdentityCredential fails fast for the first time we attempt to get token from IMDS source - either by having less retries, or having shorter intervals, or probing the IP address. Subsequent calls could take longer and have the full retry logic, in my opinion. I don't mind if ManagedIdentityCredential/IMDS fails fast only when it is being instantiated from the DefaultAzureCredential.

More thoughts: Unlike the other Azure SDKs, our intention when we introduced DefaultAzureCredential was to have a credential that we mainly use in samples, that has the highest chances of authenticating, so a user can start a client library sample without having to figure out the Identity as the first thing. We discourage people from using it in prod. Unlike other SDKs, from the get-go, we advertised it as the beginners dev-time credential, and never as a prod credential. Given all that, I think it is not that important for the user that the credential order aligns with the other SDK. It would be good, but it does not have to be. If anything, given that DefaultAzureCredential in C++ SDK is "the beginner's dev-time credential", I actually can find more sense for the dev-time credentials to be the first in the chain, not the last ones - everything is fast when you develop, and when you deploy, things may get slower, but hey, maybe it is time to pick the prod-grade credential, it will be faster.

But if we can rearrange the order and still get the token from Azure CLI in ~3 seconds, I don't mind if AzureCliCred goes after the ManagedIdentity/IMDS.

antkmsft avatar Nov 10 '23 06:11 antkmsft

Why don't we move to 1s on the IMDS request. In most cases that will result in us getting a token. And in the off chances that it doesn't then we move on quickly to the next credential. If the goal is to be aggressive in resolving a token, then customers also need to accept that we won't wait around for credentials that might come back but not for an extended period of time

RickWinter avatar Mar 01 '24 00:03 RickWinter

Here's the gist with the design of a solution for this, with the added effort to bring cross-language consistency on the behavior (see related issue https://github.com/Azure/azure-sdk-for-cpp/issues/5279): https://gist.github.com/ahsonkhan/d6c4d3a9780bb058a729b76844923ef1

ahsonkhan avatar Mar 27 '24 22:03 ahsonkhan