search

Azure / azure-sdk-for-cpp

This repository is for active development of the Azure SDK for C++. For consumers of the SDK we recommend visiting our versioned developer docs at https://azure.github.io/azure-sdk-for-cpp.
MIT License
181 stars 126 forks source link

Intermittent KeyVaultKeyClient.DoubleDeleteBeforePollComplete test failure due to 403 Reason: Forbidden #5822

Open ahsonkhan opened 3 months ago

ahsonkhan commented 3 months ago

From https://github.com/Azure/azure-sdk-for-cpp/pull/5814

On: ValidateLive Win2022_x86_no_rtti_with_unit_test https://dev.azure.com/azure-sdk/internal/_build/results?buildId=3971287&view=logs&j=2fc98781-9230-5004-8e4b-444d4f6ce9bd&t=3c1f81d9-4b69-5f1f-44df-3f6e046c3c5e

2024-07-17T23:17:33.0085076Z test 22
2024-07-17T23:17:33.0085916Z         Start  22: azure-security-keyvault-keys.KeyVaultKeyClient.DoubleDeleteBeforePollComplete
2024-07-17T23:17:33.0086337Z 
2024-07-17T23:17:33.0087453Z 22: Test command: D:\a\_work\1\s\build\sdk\keyvault\azure-security-keyvault-keys\test\ut\Release\azure-security-keyvault-keys-test.exe "--gtest_filter=KeyVaultKeyClient.DoubleDeleteBeforePollComplete" "--gtest_also_run_disabled_tests"
2024-07-17T23:17:33.0089537Z 22: Working Directory: D:/a/_work/1/s/build/sdk/keyvault/azure-security-keyvault-keys/test/ut
2024-07-17T23:17:33.0090340Z 22: Test timeout computed to be: 10000000
2024-07-17T23:17:33.0187022Z 22: Running main() from D:\a\_work\1\s\build\_deps\googletest-src\googletest\src\gtest_main.cc
2024-07-17T23:17:33.0187954Z 22: Note: Google Test filter = KeyVaultKeyClient.DoubleDeleteBeforePollComplete
2024-07-17T23:17:33.0188716Z 22: [==========] Running 1 test from 1 test suite.
2024-07-17T23:17:33.0189399Z 22: [----------] Global test environment set-up.
2024-07-17T23:17:33.0190066Z 22: [----------] 1 test from KeyVaultKeyClient
2024-07-17T23:17:33.0190668Z 22: [ RUN      ] KeyVaultKeyClient.DoubleDeleteBeforePollComplete
2024-07-17T23:17:33.0208133Z 22: [2024-07-17T23:17:33.0205580Z T: 1100] INFO  : Identity: AzurePipelinesCredential was created successfully.
2024-07-17T23:17:33.0209477Z 22: [2024-07-17T23:17:33.0206076Z T: 1100] DEBUG : Identity: Creating DefaultAzureCredential which combines mutiple parameterless credentials into a single one.
2024-07-17T23:17:33.0210972Z 22: DefaultAzureCredential is only recommended for the early stages of development, and not for usage in production environment.
2024-07-17T23:17:33.0212307Z 22: 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.
2024-07-17T23:17:33.0213360Z 22: [2024-07-17T23:17:33.0206848Z T: 1100] WARN  : Identity: EnvironmentCredential was not initialized with underlying credential.
2024-07-17T23:17:33.0214493Z 22: [2024-07-17T23:17:33.0207084Z T: 1100] 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:
2024-07-17T23:17:33.0215369Z 22:  * 'AZURE_TENANT_ID' is set
2024-07-17T23:17:33.0216114Z 22:  * 'AZURE_CLIENT_ID' is set
2024-07-17T23:17:33.0216734Z 22:  * 'AZURE_CLIENT_SECRET' is NOT set
2024-07-17T23:17:33.0217376Z 22:  * 'AZURE_CLIENT_CERTIFICATE_PATH' is NOT set
2024-07-17T23:17:33.0218008Z 22:  * 'AZURE_AUTHORITY_HOST' is set
2024-07-17T23:17:33.0218918Z 22: [2024-07-17T23:17:33.0207431Z T: 1100] WARN  : Identity: Azure Kubernetes environment is not set up for the WorkloadIdentityCredential credential to work.
2024-07-17T23:17:33.0220109Z 22: [2024-07-17T23:17:33.0207834Z T: 1100] INFO  : Identity: AzureCliCredential created.
2024-07-17T23:17:33.0221080Z 22: Successful creation does not guarantee further successful token retrieval.
2024-07-17T23:17:33.0222175Z 22: [2024-07-17T23:17:33.0208281Z T: 1100] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2019 source.
2024-07-17T23:17:33.0223265Z 22: [2024-07-17T23:17:33.0208586Z T: 1100] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with App Service 2017 source.
2024-07-17T23:17:33.0224580Z 22: [2024-07-17T23:17:33.0209195Z T: 1100] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Cloud Shell source.
2024-07-17T23:17:33.0225799Z 22: [2024-07-17T23:17:33.0209686Z T: 1100] DEBUG : Identity: ManagedIdentityCredential: Environment is not set up for the credential to be created with Azure Arc source.
2024-07-17T23:17:33.0226803Z 22: [2024-07-17T23:17:33.0209942Z T: 1100] INFO  : Identity: ManagedIdentityCredential will be created with Azure Instance Metadata Service source.
2024-07-17T23:17:33.0227629Z 22: Successful creation does not guarantee further successful token retrieval.
2024-07-17T23:17:33.0228724Z 22: [2024-07-17T23:17:33.0210593Z T: 1100] INFO  : Identity: DefaultAzureCredential: Created with the following credentials: EnvironmentCredential, WorkloadIdentityCredential, AzureCliCredential, ManagedIdentityCredential.
2024-07-17T23:17:33.0229917Z 22: [2024-07-17T23:17:33.0210914Z T: 1100] INFO  : Identity: ChainedTokenCredential: Created with the following credentials: AzurePipelinesCredential, DefaultAzureCredential.
2024-07-17T23:17:33.0230696Z 22: 
2024-07-17T23:17:33.0231828Z 22:  Keyvault and HSM areSame[2024-07-17T23:17:33.0217763Z T: 1100] INFO  : HTTP Request : POST https://dev.azure.com/azure-sdk/590cfd2a-581c-4dcb-a12e-6568ce786175/_apis/distributedtask/hubs/build/plans/5eeb7511-2951-4648-b2e2-d78e2917aba4/jobs/2fc98781-9230-5004-8e4b-444d4f6ce9bd/oidctoken?api-version=7.1&serviceConnectionId=REDACTED
2024-07-17T23:17:33.0232789Z 22: authorization : REDACTED
2024-07-17T23:17:33.0233575Z 22: content-type : application/json
2024-07-17T23:17:33.0234569Z 22: user-agent : azsdk-cpp-identity/1.9.0-beta.2 (Windows Server 2022 Datacenter 6.3 20348 20348.1.amd64fre.fe_release.210507-1500)
2024-07-17T23:17:33.0235457Z 22: x-ms-client-request-id : bba3a26d-e852-4002-a58e-fafaba095c06
2024-07-17T23:17:33.0276799Z 22: [2024-07-17T23:17:33.0275089Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:17:33.0302126Z 22: [2024-07-17T23:17:33.0300427Z T: 3176] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:17:33.0311172Z 22: [2024-07-17T23:17:33.0309620Z T: 3176] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
2024-07-17T23:17:54.0884587Z 22: [2024-07-17T23:17:54.0880262Z T: 3176] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
2024-07-17T23:17:54.0886420Z 22: [2024-07-17T23:17:54.0882858Z T: 3176] ERROR : Request error:  Error Code: 12002: The operation timed out. Failing API: API_SEND_REQUEST
2024-07-17T23:17:54.0888186Z 22: [2024-07-17T23:17:54.0883693Z T: 1100] ERROR : Action completed with error:  Error Code: 12002: The operation timed out.
2024-07-17T23:17:54.0889909Z 22: [2024-07-17T23:17:54.0885594Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
2024-07-17T23:17:54.0890931Z 22: [2024-07-17T23:17:54.0886357Z T: 1100] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
2024-07-17T23:17:54.0891583Z 22: [2024-07-17T23:17:54.0886641Z T: 1100] DEBUG : Closing handle; completing outstanding Close request
2024-07-17T23:17:54.0892216Z 22: [2024-07-17T23:17:54.0886901Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Handle closed.
2024-07-17T23:17:54.0892896Z 22: [2024-07-17T23:17:54.0887707Z T: 1100] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out.
2024-07-17T23:17:54.0893577Z 22: [2024-07-17T23:17:54.0888263Z T: 1100] INFO  : HTTP Retry attempt #1 will be made in 640ms.
2024-07-17T23:17:54.7427107Z 22: [2024-07-17T23:17:54.7423138Z T: 1100] INFO  : HTTP Request : POST https://dev.azure.com/azure-sdk/590cfd2a-581c-4dcb-a12e-6568ce786175/_apis/distributedtask/hubs/build/plans/5eeb7511-2951-4648-b2e2-d78e2917aba4/jobs/2fc98781-9230-5004-8e4b-444d4f6ce9bd/oidctoken?api-version=7.1&serviceConnectionId=REDACTED
2024-07-17T23:17:54.7428339Z 22: authorization : REDACTED
2024-07-17T23:17:54.7429054Z 22: content-type : application/json
2024-07-17T23:17:54.7429978Z 22: user-agent : azsdk-cpp-identity/1.9.0-beta.2 (Windows Server 2022 Datacenter 6.3 20348 20348.1.amd64fre.fe_release.210507-1500)
2024-07-17T23:17:54.7431082Z 22: x-ms-client-request-id : bba3a26d-e852-4002-a58e-fafaba095c06
2024-07-17T23:17:54.7432205Z 22: [2024-07-17T23:17:54.7429195Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:17:54.7433207Z 22: [2024-07-17T23:17:54.7429859Z T: 5740] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:17:54.7434088Z 22: [2024-07-17T23:17:54.7430180Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:17:54.7469147Z 22: [2024-07-17T23:17:54.7466951Z T: 3176] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:17:54.7470099Z 22: [2024-07-17T23:17:54.7468137Z T: 3176] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
2024-07-17T23:18:15.7905541Z 22: [2024-07-17T23:18:15.7902169Z T: 3176] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
2024-07-17T23:18:15.7907086Z 22: [2024-07-17T23:18:15.7903043Z T: 3176] ERROR : Request error:  Error Code: 12002: The operation timed out. Failing API: API_SEND_REQUEST
2024-07-17T23:18:15.7908157Z 22: [2024-07-17T23:18:15.7903686Z T: 1100] ERROR : Action completed with error:  Error Code: 12002: The operation timed out.
2024-07-17T23:18:15.7909137Z 22: [2024-07-17T23:18:15.7904799Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
2024-07-17T23:18:15.7910227Z 22: [2024-07-17T23:18:15.7905504Z T: 1100] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
2024-07-17T23:18:15.7910990Z 22: [2024-07-17T23:18:15.7905733Z T: 1100] DEBUG : Closing handle; completing outstanding Close request
2024-07-17T23:18:15.7911663Z 22: [2024-07-17T23:18:15.7906042Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Handle closed.
2024-07-17T23:18:15.7912373Z 22: [2024-07-17T23:18:15.7906366Z T: 1100] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out.
2024-07-17T23:18:15.7913055Z 22: [2024-07-17T23:18:15.7906644Z T: 1100] INFO  : HTTP Retry attempt #2 will be made in 1730ms.
2024-07-17T23:18:17.5300266Z 22: [2024-07-17T23:18:17.5295639Z T: 1100] INFO  : HTTP Request : POST https://dev.azure.com/azure-sdk/590cfd2a-581c-4dcb-a12e-6568ce786175/_apis/distributedtask/hubs/build/plans/5eeb7511-2951-4648-b2e2-d78e2917aba4/jobs/2fc98781-9230-5004-8e4b-444d4f6ce9bd/oidctoken?api-version=7.1&serviceConnectionId=REDACTED
2024-07-17T23:18:17.5301792Z 22: authorization : REDACTED
2024-07-17T23:18:17.5302769Z 22: content-type : application/json
2024-07-17T23:18:17.5303881Z 22: user-agent : azsdk-cpp-identity/1.9.0-beta.2 (Windows Server 2022 Datacenter 6.3 20348 20348.1.amd64fre.fe_release.210507-1500)
2024-07-17T23:18:17.5305269Z 22: x-ms-client-request-id : bba3a26d-e852-4002-a58e-fafaba095c06
2024-07-17T23:18:17.5306416Z 22: [2024-07-17T23:18:17.5301601Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:18:17.5307236Z 22: [2024-07-17T23:18:17.5302213Z T: 5740] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:18:17.5307939Z 22: [2024-07-17T23:18:17.5302524Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:18:17.5332684Z 22: [2024-07-17T23:18:17.5323946Z T: 3176] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:18:17.5333711Z 22: [2024-07-17T23:18:17.5325015Z T: 3176] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
2024-07-17T23:18:38.5740196Z 22: [2024-07-17T23:18:38.5734298Z T: 3176] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
2024-07-17T23:18:39.5894836Z 22: [2024-07-17T23:18:38.5735243Z T: 3176] ERROR : Request error:  Error Code: 12002: The operation timed out. Failing API: API_SEND_REQUEST
2024-07-17T23:18:39.5896620Z 22: [2024-07-17T23:18:38.5736144Z T: 1100] ERROR : Action completed with error:  Error Code: 12002: The operation timed out.
2024-07-17T23:18:39.5897992Z 22: [2024-07-17T23:18:38.5737257Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
2024-07-17T23:18:39.5899283Z 22: [2024-07-17T23:18:38.5737603Z T: 1100] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
2024-07-17T23:18:39.5900384Z 22: [2024-07-17T23:18:38.5738250Z T: 1100] DEBUG : Closing handle; completing outstanding Close request
2024-07-17T23:18:39.5901377Z 22: [2024-07-17T23:18:38.5738524Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Handle closed.
2024-07-17T23:18:39.5902677Z 22: [2024-07-17T23:18:38.5738991Z T: 1100] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out.
2024-07-17T23:18:39.5903698Z 22: [2024-07-17T23:18:38.5739379Z T: 1100] INFO  : HTTP Retry attempt #3 will be made in 2869ms.
2024-07-17T23:18:41.4567053Z 22: [2024-07-17T23:18:41.4563185Z T: 1100] INFO  : HTTP Request : POST https://dev.azure.com/azure-sdk/590cfd2a-581c-4dcb-a12e-6568ce786175/_apis/distributedtask/hubs/build/plans/5eeb7511-2951-4648-b2e2-d78e2917aba4/jobs/2fc98781-9230-5004-8e4b-444d4f6ce9bd/oidctoken?api-version=7.1&serviceConnectionId=REDACTED
2024-07-17T23:18:41.4568704Z 22: authorization : REDACTED
2024-07-17T23:18:41.4569704Z 22: content-type : application/json
2024-07-17T23:18:41.4571140Z 22: user-agent : azsdk-cpp-identity/1.9.0-beta.2 (Windows Server 2022 Datacenter 6.3 20348 20348.1.amd64fre.fe_release.210507-1500)
2024-07-17T23:18:41.4572772Z 22: x-ms-client-request-id : bba3a26d-e852-4002-a58e-fafaba095c06
2024-07-17T23:18:41.4574285Z 22: [2024-07-17T23:18:41.4569515Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:18:41.4575726Z 22: [2024-07-17T23:18:41.4570597Z T: 5740] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:18:41.4576967Z 22: [2024-07-17T23:18:41.4571233Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:18:41.4594535Z 22: [2024-07-17T23:18:41.4592903Z T: 3176] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:18:41.4596468Z 22: [2024-07-17T23:18:41.4594076Z T: 3176] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
2024-07-17T23:19:02.5034945Z 22: [2024-07-17T23:19:02.5031238Z T: 5740] INFO  : Status operation: 2097152(WINHTTP_CALLBACK_STATUS_REQUEST_ERROR )
2024-07-17T23:19:02.5037468Z 22: [2024-07-17T23:19:02.5032317Z T: 5740] ERROR : Request error:  Error Code: 12002: The operation timed out. Failing API: API_SEND_REQUEST
2024-07-17T23:19:02.5039272Z 22: [2024-07-17T23:19:02.5033008Z T: 1100] ERROR : Action completed with error:  Error Code: 12002: The operation timed out.
2024-07-17T23:19:02.5040861Z 22: [2024-07-17T23:19:02.5033948Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
2024-07-17T23:19:02.5042183Z 22: [2024-07-17T23:19:02.5034581Z T: 1100] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
2024-07-17T23:19:02.5043329Z 22: [2024-07-17T23:19:02.5034905Z T: 1100] DEBUG : Closing handle; completing outstanding Close request
2024-07-17T23:19:02.5044316Z 22: [2024-07-17T23:19:02.5035251Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Handle closed.
2024-07-17T23:19:02.5045359Z 22: [2024-07-17T23:19:02.5035835Z T: 1100] WARN  : HTTP Transport error: Error while waiting for a send to complete. Error Code: 12002: The operation timed out.
2024-07-17T23:19:02.5046525Z 22: [2024-07-17T23:19:02.5037374Z T: 1100] DEBUG : Identity: ChainedTokenCredential: Failed to get token from AzurePipelinesCredential: GetToken(): Error while waiting for a send to complete. Error Code: 12002: The operation timed out.
2024-07-17T23:19:02.5047660Z 22: [2024-07-17T23:19:02.5037995Z T: 1100] WARN  : Identity: EnvironmentCredential authentication unavailable. See earlier EnvironmentCredential log messages for details.
2024-07-17T23:19:02.5048797Z 22: [2024-07-17T23:19:02.5038456Z T: 1100] DEBUG : Identity: DefaultAzureCredential: Failed to get token from EnvironmentCredential: EnvironmentCredential authentication unavailable. Environment variables are not fully configured.
2024-07-17T23:19:02.5049986Z 22: [2024-07-17T23:19:02.5038765Z T: 1100] WARN  : Identity: WorkloadIdentityCredential authentication unavailable. See earlier WorkloadIdentityCredential log messages for details.
2024-07-17T23:19:02.5051144Z 22: [2024-07-17T23:19:02.5039148Z T: 1100] DEBUG : Identity: DefaultAzureCredential: Failed to get token from WorkloadIdentityCredential: WorkloadIdentityCredential authentication unavailable. Azure Kubernetes environment is not set up correctly.
2024-07-17T23:21:47.3744394Z 22: [2024-07-17T23:21:47.3739279Z T: 1100] WARN  : Identity: AzureCliCredential didn't get the token: "Azure CLI process took too long to complete."
2024-07-17T23:21:47.3746589Z 22: [2024-07-17T23:21:47.3740171Z T: 1100] DEBUG : Identity: DefaultAzureCredential: Failed to get token from AzureCliCredential: AzureCliCredential didn't get the token: "Azure CLI process took too long to complete."
2024-07-17T23:21:47.3748207Z 22: [2024-07-17T23:21:47.3741112Z T: 1100] INFO  : HTTP Request : GET http://169.254.169.254/metadata/identity/oauth2/token?api-version=2018-02-01&resource=REDACTED
2024-07-17T23:21:47.3749420Z 22: metadata : REDACTED
2024-07-17T23:21:47.3750548Z 22: user-agent : azsdk-cpp-identity/1.9.0-beta.2 (Windows Server 2022 Datacenter 6.3 20348 20348.1.amd64fre.fe_release.210507-1500)
2024-07-17T23:21:47.3751889Z 22: x-ms-client-request-id : ffc852d3-4bef-41d4-885d-9d3e5b19e160
2024-07-17T23:21:47.3753074Z 22: [2024-07-17T23:21:47.3748809Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:21:47.3754084Z 22: [2024-07-17T23:21:47.3749531Z T: 5740] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:21:47.3755048Z 22: [2024-07-17T23:21:47.3750912Z T: 5740] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
2024-07-17T23:21:47.3758273Z 22: [2024-07-17T23:21:47.3756257Z T: 5740] INFO  : Status operation: 8(WINHTTP_CALLBACK_STATUS_CONNECTED_TO_SERVER )
2024-07-17T23:21:47.3759291Z 22: [2024-07-17T23:21:47.3756734Z T: 5740] INFO  : Status operation: 16(WINHTTP_CALLBACK_STATUS_SENDING_REQUEST )
2024-07-17T23:21:47.3760092Z 22: [2024-07-17T23:21:47.3757300Z T: 5740] INFO  : Status operation: 32(WINHTTP_CALLBACK_STATUS_REQUEST_SENT )
2024-07-17T23:21:47.4177610Z 22: [2024-07-17T23:21:47.4175228Z T: 5740] INFO  : Status operation: 4194304(WINHTTP_CALLBACK_STATUS_SENDREQUEST_COMPLETE )
2024-07-17T23:21:47.4179665Z 22: [2024-07-17T23:21:47.4176058Z T: 1100] INFO  : Status operation: 64(WINHTTP_CALLBACK_STATUS_RECEIVING_RESPONSE )
2024-07-17T23:21:47.4182461Z 22: [2024-07-17T23:21:47.4176385Z T: 1100] INFO  : Status operation: 128(WINHTTP_CALLBACK_STATUS_RESPONSE_RECEIVED )
2024-07-17T23:21:47.4183795Z 22: [2024-07-17T23:21:47.4176693Z T: 1100] INFO  : Status operation: 131072(WINHTTP_CALLBACK_STATUS_HEADERS_AVAILABLE )
2024-07-17T23:21:47.4185036Z 22: [2024-07-17T23:21:47.4177479Z T: 1100] INFO  : Status operation: 64(WINHTTP_CALLBACK_STATUS_RECEIVING_RESPONSE )
2024-07-17T23:21:47.4186247Z 22: [2024-07-17T23:21:47.4177896Z T: 1100] INFO  : Status operation: 128(WINHTTP_CALLBACK_STATUS_RESPONSE_RECEIVED )
2024-07-17T23:21:47.4187464Z 22: [2024-07-17T23:21:47.4178235Z T: 1100] INFO  : Status operation: 524288(WINHTTP_CALLBACK_STATUS_READ_COMPLETE )
2024-07-17T23:21:47.4188708Z 22: [2024-07-17T23:21:47.4178573Z T: 1100] DEBUG : Read Data read from wire. Size: 2010.
2024-07-17T23:21:47.4189863Z 22: [2024-07-17T23:21:47.4179095Z T: 1100] DEBUG : ReadData returned size: 2010.
2024-07-17T23:21:47.4190959Z 22: [2024-07-17T23:21:47.4179470Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
2024-07-17T23:21:47.4192091Z 22: [2024-07-17T23:21:47.4179995Z T: 1100] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
2024-07-17T23:21:47.4192806Z 22: [2024-07-17T23:21:47.4180250Z T: 1100] DEBUG : Closing handle; completing outstanding Close request
2024-07-17T23:21:47.4193546Z 22: [2024-07-17T23:21:47.4180525Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Handle closed.
2024-07-17T23:21:47.4194161Z 22: [2024-07-17T23:21:47.4181150Z T: 1100] INFO  : HTTP/1.1 Response (43ms) : 200 OK
2024-07-17T23:21:47.4194647Z 22: content-length : 2010
2024-07-17T23:21:47.4195125Z 22: content-type : application/json; charset=utf-8
2024-07-17T23:21:47.4195557Z 22: date : Wed, 17 Jul 2024 23:21:47 GMT
2024-07-17T23:21:47.4195956Z 22: server : IMDS/150.870.65.1305
2024-07-17T23:21:47.4196588Z 22: x-ms-request-id : 6c8989ec-de56-410f-ac1f-c2a1cb86df02
2024-07-17T23:21:47.4197145Z 22: [2024-07-17T23:21:47.4181423Z T: 1100] INFO  : HTTP status code 200 won't be retried.
2024-07-17T23:21:47.4197870Z 22: [2024-07-17T23:21:47.4182523Z T: 1100] INFO  : Identity: DefaultAzureCredential: Successfully got token from ManagedIdentityCredential. This credential will be reused for subsequent calls.
2024-07-17T23:21:47.4198611Z 22: [2024-07-17T23:21:47.4182827Z T: 1100] DEBUG : Identity: DefaultAzureCredential: Saved this credential at index 3 for subsequent calls.
2024-07-17T23:21:47.4199293Z 22: [2024-07-17T23:21:47.4183081Z T: 1100] INFO  : Identity: ChainedTokenCredential: Successfully got token from DefaultAzureCredential.
2024-07-17T23:21:47.4200102Z 22: [2024-07-17T23:21:47.4183606Z T: 1100] INFO  : HTTP Request : POST ***keys/DoubleDeleteBeforePollComplete/create?api-version=7.5
2024-07-17T23:21:47.4200595Z 22: authorization : REDACTED
2024-07-17T23:21:47.4201035Z 22: content-type : application/json
2024-07-17T23:21:47.4201632Z 22: user-agent : azsdk-cpp-keyvault-keys/4.5.0-beta.3 (Windows Server 2022 Datacenter 6.3 20348 20348.1.amd64fre.fe_release.210507-1500)
2024-07-17T23:21:47.4202229Z 22: x-ms-client-request-id : 02394973-593a-4c87-a557-4ded822028ee
2024-07-17T23:21:47.4202822Z 22: [2024-07-17T23:21:47.4188057Z T: 5740] INFO  : Status operation: 1(WINHTTP_CALLBACK_STATUS_RESOLVING_NAME )
2024-07-17T23:21:47.4231123Z 22: [2024-07-17T23:21:47.4228807Z T: 2620] INFO  : Status operation: 2(WINHTTP_CALLBACK_STATUS_NAME_RESOLVED )
2024-07-17T23:21:47.4232050Z 22: [2024-07-17T23:21:47.4230035Z T: 2620] INFO  : Status operation: 4(WINHTTP_CALLBACK_STATUS_CONNECTING_TO_SERVER )
2024-07-17T23:21:47.4246476Z 22: [2024-07-17T23:21:47.4244764Z T: 2620] INFO  : Status operation: 8(WINHTTP_CALLBACK_STATUS_CONNECTED_TO_SERVER )
2024-07-17T23:21:47.4363788Z 22: [2024-07-17T23:21:47.4360953Z T: 2620] INFO  : Status operation: 16(WINHTTP_CALLBACK_STATUS_SENDING_REQUEST )
2024-07-17T23:21:47.4365203Z 22: [2024-07-17T23:21:47.4361952Z T: 2620] INFO  : Status operation: 32(WINHTTP_CALLBACK_STATUS_REQUEST_SENT )
2024-07-17T23:21:47.4366393Z 22: [2024-07-17T23:21:47.4362851Z T: 5740] INFO  : Status operation: 4194304(WINHTTP_CALLBACK_STATUS_SENDREQUEST_COMPLETE )
2024-07-17T23:21:47.4367278Z 22: [2024-07-17T23:21:47.4363566Z T: 1100] INFO  : Status operation: 16(WINHTTP_CALLBACK_STATUS_SENDING_REQUEST )
2024-07-17T23:21:47.4369261Z 22: [2024-07-17T23:21:47.4367563Z T: 2620] INFO  : Status operation: 32(WINHTTP_CALLBACK_STATUS_REQUEST_SENT )
2024-07-17T23:21:47.4370573Z 22: [2024-07-17T23:21:47.4368014Z T: 2620] INFO  : Status operation: 1048576(WINHTTP_CALLBACK_STATUS_WRITE_COMPLETE )
2024-07-17T23:21:47.4371401Z 22: [2024-07-17T23:21:47.4368596Z T: 1100] INFO  : Status operation: 64(WINHTTP_CALLBACK_STATUS_RECEIVING_RESPONSE )
2024-07-17T23:21:47.4500449Z 22: [2024-07-17T23:21:47.4498127Z T: 2620] INFO  : Status operation: 128(WINHTTP_CALLBACK_STATUS_RESPONSE_RECEIVED )
2024-07-17T23:21:47.4502013Z 22: [2024-07-17T23:21:47.4498533Z T: 2620] INFO  : Status operation: 131072(WINHTTP_CALLBACK_STATUS_HEADERS_AVAILABLE )
2024-07-17T23:21:47.4503578Z 22: [2024-07-17T23:21:47.4499527Z T: 1100] INFO  : Status operation: 64(WINHTTP_CALLBACK_STATUS_RECEIVING_RESPONSE )
2024-07-17T23:21:47.4505195Z 22: [2024-07-17T23:21:47.4500148Z T: 1100] INFO  : Status operation: 128(WINHTTP_CALLBACK_STATUS_RESPONSE_RECEIVED )
2024-07-17T23:21:47.4506582Z 22: [2024-07-17T23:21:47.4500484Z T: 1100] INFO  : Status operation: 524288(WINHTTP_CALLBACK_STATUS_READ_COMPLETE )
2024-07-17T23:21:47.4507698Z 22: [2024-07-17T23:21:47.4500938Z T: 1100] DEBUG : Read Data read from wire. Size: 439.
2024-07-17T23:21:47.4508932Z 22: [2024-07-17T23:21:47.4501325Z T: 1100] DEBUG : ReadData returned size: 439.
2024-07-17T23:21:47.4509999Z 22: [2024-07-17T23:21:47.4501642Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Closing handle synchronously.
2024-07-17T23:21:47.4511150Z 22: [2024-07-17T23:21:47.4502122Z T: 1100] INFO  : Status operation: 2048(WINHTTP_CALLBACK_STATUS_HANDLE_CLOSING )
2024-07-17T23:21:47.4512382Z 22: [2024-07-17T23:21:47.4502434Z T: 1100] DEBUG : Closing handle; completing outstanding Close request
2024-07-17T23:21:47.4513408Z 22: [2024-07-17T23:21:47.4502766Z T: 1100] INFO  : WinHttpRequest::~WinHttpRequest. Handle closed.
2024-07-17T23:21:47.4514329Z 22: [2024-07-17T23:21:47.4503351Z T: 1100] INFO  : HTTP/1.1 Response (31ms) : 403 Forbidden
2024-07-17T23:21:47.4515081Z 22: cache-control : no-cache
2024-07-17T23:21:47.4515802Z 22: content-length : 439
2024-07-17T23:21:47.4516461Z 22: content-type : application/json; charset=utf-8
2024-07-17T23:21:47.4517069Z 22: date : Wed, 17 Jul 2024 23:21:47 GMT
2024-07-17T23:21:47.4518084Z 22: expires : -1
2024-07-17T23:21:47.4518860Z 22: pragma : no-cache
2024-07-17T23:21:47.4519685Z 22: strict-transport-security : REDACTED
2024-07-17T23:21:47.4520513Z 22: x-content-type-options : REDACTED
2024-07-17T23:21:47.4521398Z 22: x-ms-client-request-id : 02394973-593a-4c87-a557-4ded822028ee
2024-07-17T23:21:47.4522366Z 22: x-ms-keyvault-network-info : REDACTED
2024-07-17T23:21:47.4523144Z 22: x-ms-keyvault-region : REDACTED
2024-07-17T23:21:47.4523932Z 22: x-ms-keyvault-service-version : REDACTED
2024-07-17T23:21:47.4524777Z 22: x-ms-request-id : 8779f4db-c64e-47d4-8f78-3e88a2b0fc49
2024-07-17T23:21:47.4525693Z 22: [2024-07-17T23:21:47.4504024Z T: 1100] INFO  : HTTP status code 403 won't be retried.
2024-07-17T23:21:47.4526932Z 22: unknown file: error: C++ exception with description "Received an HTTP unsuccessful status code: 403 Reason: Forbidden" thrown in the test body.
2024-07-17T23:21:47.4528156Z 22: [  FAILED  ] KeyVaultKeyClient.DoubleDeleteBeforePollComplete (254436 ms)
gearama commented 3 months ago

Based on the logs this comes from identity not working, since the other tests pass it seesm the issue is an intermittent one coming out of identity 403 is due to an inability to get a valid token

ahsonkhan commented 2 months ago

@gearama, yes the initial attempts to fetch the token failed, but the retry policy kicked in and you can see a successful token fetch at retry attempt 3, down below:

...
2024-07-17T23:21:47.4197145Z 22: [2024-07-17T23:21:47.4181423Z T: 1100] INFO  : HTTP status code 200 won't be retried.
2024-07-17T23:21:47.4197870Z 22: [2024-07-17T23:21:47.4182523Z T: 1100] INFO  : Identity: DefaultAzureCredential: Successfully got token from ManagedIdentityCredential. This credential will be reused for subsequent calls.
2024-07-17T23:21:47.4198611Z 22: [2024-07-17T23:21:47.4182827Z T: 1100] DEBUG : Identity: DefaultAzureCredential: Saved this credential at index 3 for subsequent calls.
2024-07-17T23:21:47.4199293Z 22: [2024-07-17T23:21:47.4183081Z T: 1100] INFO  : Identity: ChainedTokenCredential: Successfully got token from DefaultAzureCredential.
2024-07-17T23:21:47.4200102Z 22: [2024-07-17T23:21:47.4183606Z T: 1100] INFO  : HTTP Request : POST ***keys/DoubleDeleteBeforePollComplete/create?api-version=7.5
...
2024-07-17T23:21:47.4514329Z 22: [2024-07-17T23:21:47.4503351Z T: 1100] INFO  : HTTP/1.1 Response (31ms) : 403 Forbidden

The 403 then comes when the POST request is made to the keyvault endpoint, and not the identity endpoint.