search

Azure / azure-cli

Azure Command-Line Interface
MIT License
3.97k stars 2.95k forks source link

Encountered internal server error while processing the deployment what-if request #28355

Closed cwistedt closed 7 months ago

cwistedt commented 7 months ago

Describe the bug

I am trying to run az deploy what-if and keep getting InternalServerError as output and the command fails:

The Comman: az deployment sub what-if --name '' --location 'westeurope' --template-file '' --parameter ''

Related command

none

Errors

ERROR: InternalServerError - Encountered internal server error while processing the deployment what-if request. Diagnostic information: timestamp '20240212T060623Z', scope '/subscriptions/[removed]', tracking id '00d61cb6-aebf-42b4-acb0-e62506c5e084', request correlation id '1fa26211-3696-47ba-a6f9-9499bbce2c1b'.

Issue script & Debug output

DEBUG: cli.azure.cli.core.util: attempting to read file Resources/Solutions/[Removed]]/test.parameters.json as utf-8-sig DEBUG: cli.azure.cli.core.commands.client_factory: Getting management service client client_type=ResourceManagementClient DEBUG: cli.azure.cli.core.auth.persistence: build_persistence: location='/home/vsts/work/_temp/.azclitask/service_principal_entries.json', encrypt=False DEBUG: cli.azure.cli.core.auth.persistence: build_persistence: location='/home/vsts/work/_temp/.azclitask/msal_token_cache.json', encrypt=False DEBUG: cli.azure.cli.core.auth.binary_cache: load: /home/vsts/work/_temp/.azclitask/msal_http_cache.bin DEBUG: urllib3.util.retry: Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None) DEBUG: msal.authority: openid_config = {'token_endpoint': 'https://login.microsoftonline.com/[removed]/oauth2/v2.0/token', 'token_endpoint_auth_methods_supported': ['client_secret_post', 'private_key_jwt', 'client_secret_basic'], 'jwks_uri': 'https://login.microsoftonline.com/[removed]/discovery/v2.0/keys', 'response_modes_supported': ['query', 'fragment', 'form_post'], 'subject_types_supported': ['pairwise'], 'id_token_signing_alg_values_supported': ['RS256'], 'response_types_supported': ['code', 'id_token', 'code id_token', 'id_token token'], 'scopes_supported': ['openid', 'profile', 'email', 'offline_access'], 'issuer': 'https://login.microsoftonline.com/[removed]/v2.0', 'request_uri_parameter_supported': False, 'userinfo_endpoint': 'https://graph.microsoft.com/oidc/userinfo', 'authorization_endpoint': 'https://login.microsoftonline.com/[removed]/oauth2/v2.0/authorize', 'device_authorization_endpoint': 'https://login.microsoftonline.com/[removed]/oauth2/v2.0/devicecode', 'http_logout_supported': True, 'frontchannel_logout_supported': True, 'end_session_endpoint': 'https://login.microsoftonline.com/[removed]/oauth2/v2.0/logout', 'claims_supported': ['sub', 'iss', 'cloud_instance_name', 'cloud_instance_host_name', 'cloud_graph_host_name', 'msgraph_host', 'aud', 'exp', 'iat', 'auth_time', 'acr', 'nonce', 'preferred_username', 'name', 'tid', 'ver', 'at_hash', 'c_hash', 'email'], 'kerberos_endpoint': 'https://login.microsoftonline.com/[removed]/kerberos', 'tenant_region_scope': 'EU', 'cloud_instance_name': 'microsoftonline.com', 'cloud_graph_host_name': 'graph.windows.net', 'msgraph_host': 'graph.microsoft.com', 'rbac_url': 'https://pas.windows.net'} DEBUG: msal.application: Broker enabled? False DEBUG: msal.application: Region to be used: None DEBUG: cli.azure.cli.core.auth.credential_adaptor: CredentialAdaptor.get_token: scopes=('https://management.core.windows.net//.default',), kwargs={} DEBUG: cli.azure.cli.core.auth.msal_authentication: ServicePrincipalCredential.get_token: scopes=('https://management.core.windows.net//.default',), kwargs={} DEBUG: msal.application: Cache hit an AT DEBUG: msal.telemetry: Generate or reuse correlation_id: [removed] DEBUG: cli.azure.cli.core.sdk.policies: Request URL: 'https://management.azure.com/subscriptions/[removed]/providers/Microsoft.Resources/deployments/rdm-iac-sxdm-test/whatIf?api-version=2022-09-01' DEBUG: cli.azure.cli.core.sdk.policies: Request method: 'POST' DEBUG: cli.azure.cli.core.sdk.policies: Request headers: DEBUG: cli.azure.cli.core.sdk.policies: 'Content-Type': 'application/json' DEBUG: cli.azure.cli.core.sdk.policies: 'Content-Length': '54077' DEBUG: cli.azure.cli.core.sdk.policies: 'Accept': 'application/json' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-client-request-id': '[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'CommandName': 'deployment sub what-if' DEBUG: cli.azure.cli.core.sdk.policies: 'ParameterSetName': '--name --location --template-file --parameter --debug' DEBUG: cli.azure.cli.core.sdk.policies: 'User-Agent': 'AZURECLI/2.56.0 (DEB) azsdk-python-azure-mgmt-resource/23.1.0b2 Python/3.11.5 (Linux-6.2.0-1019-azure-x8664-with-glibc2.35) VSTS[removed]_build_543_0' DEBUG: cli.azure.cli.core.sdk.policies: 'Authorization': '' DEBUG: cli.azure.cli.core.sdk.policies: Request body: DEBUG: cli.azure.cli.core.sdk.policies: [Removed] DEBUG: cli.azure.cli.command_modules.resource.custom: HTTP content is being overwritten to preserve template whitepace accurately. The request body logging may not accurately represent this. DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): management.azure.com:443 DEBUG: urllib3.connectionpool: https://management.azure.com:443 "POST /subscriptions/[removed]/providers/Microsoft.Resources/deployments/rdm-iac-sxdm-test/whatIf?api-version=2022-09-01 HTTP/1.1" 202 0 DEBUG: cli.azure.cli.core.sdk.policies: Response status: 202 DEBUG: cli.azure.cli.core.sdk.policies: Response headers: DEBUG: cli.azure.cli.core.sdk.policies: 'Cache-Control': 'no-cache' DEBUG: cli.azure.cli.core.sdk.policies: 'Pragma': 'no-cache' DEBUG: cli.azure.cli.core.sdk.policies: 'Expires': '-1' DEBUG: cli.azure.cli.core.sdk.policies: 'Location': 'https://management.azure.com/subscriptions/[removed]/operationresults/[removed]?api-version=2022-09-01&t=638433164466718140&c=[Removed]&s=[Removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'Retry-After': '15' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-ratelimit-remaining-subscription-writes': '1199' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-request-id': '[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-correlation-request-id': '[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-routing-request-id': 'WESTEUROPE:20240212T063406Z:[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains' DEBUG: cli.azure.cli.core.sdk.policies: 'X-Content-Type-Options': 'nosniff' DEBUG: cli.azure.cli.core.sdk.policies: 'Date': 'Mon, 12 Feb 2024 06:34:06 GMT' DEBUG: cli.azure.cli.core.sdk.policies: 'Content-Length': '0' DEBUG: cli.azure.cli.core.sdk.policies: Response content: DEBUG: cli.azure.cli.core.sdk.policies: DEBUG: cli.azure.cli.core.sdk.policies: Request URL: 'https://management.azure.com/subscriptions/[removed]/operationresults/[removed]?api-version=2022-09-01&t=638433164466718140&c=[Removed]&s=[Removed]' DEBUG: cli.azure.cli.core.sdk.policies: Request method: 'GET' DEBUG: cli.azure.cli.core.sdk.policies: Request headers: DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-client-request-id': '[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'CommandName': 'deployment sub what-if' DEBUG: cli.azure.cli.core.sdk.policies: 'ParameterSetName': '--name --location --template-file --parameter --debug' DEBUG: cli.azure.cli.core.sdk.policies: 'User-Agent': 'AZURECLI/2.56.0 (DEB) azsdk-python-azure-mgmt-resource/23.1.0b2 Python/3.11.5 (Linux-6.2.0-1019-azure-x8664-with-glibc2.35) VSTS[removed]_build_543_0' DEBUG: cli.azure.cli.core.sdk.policies: 'Authorization': '' DEBUG: cli.azure.cli.core.sdk.policies: Request body: DEBUG: cli.azure.cli.core.sdk.policies: This request has no body DEBUG: urllib3.connectionpool: https://management.azure.com:443 "GET /subscriptions/[removed]/operationresults/[removed]?api-version=2022-09-01&t=638433164466718140&c=[Removed]&s=[Removed] HTTP/1.1" 202 0 DEBUG: cli.azure.cli.core.sdk.policies: Response status: 202 DEBUG: cli.azure.cli.core.sdk.policies: Response headers: DEBUG: cli.azure.cli.core.sdk.policies: 'Cache-Control': 'no-cache' DEBUG: cli.azure.cli.core.sdk.policies: 'Pragma': 'no-cache' DEBUG: cli.azure.cli.core.sdk.policies: 'Expires': '-1' DEBUG: cli.azure.cli.core.sdk.policies: 'Location': 'https://management.azure.com/subscriptions/[removed]/operationresults/[removed]?api-version=2022-09-01&t=638433164467030698&c=[Removed]&s=[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'Retry-After': '15' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-ratelimit-remaining-subscription-reads': '11999' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-request-id': '[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-correlation-request-id': '[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-routing-request-id': 'WESTEUROPE:20240212T063406Z:[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains' DEBUG: cli.azure.cli.core.sdk.policies: 'X-Content-Type-Options': 'nosniff' DEBUG: cli.azure.cli.core.sdk.policies: 'Date': 'Mon, 12 Feb 2024 06:34:06 GMT' DEBUG: cli.azure.cli.core.sdk.policies: 'Content-Length': '0' DEBUG: cli.azure.cli.core.sdk.policies: Response content: DEBUG: cli.azure.cli.core.sdk.policies: DEBUG: cli.azure.cli.core.sdk.policies: Request URL: 'https://management.azure.com/subscriptions/[removed]/operationresults/[removed]?api-version=2022-09-01&t=638433164467030698&c=[Removed]&s=[removed]' DEBUG: cli.azure.cli.core.sdk.policies: Request method: 'GET' DEBUG: cli.azure.cli.core.sdk.policies: Request headers: DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-client-request-id': '[removed]' DEBUG: cli.azure.cli.core.sdk.policies: 'CommandName': 'deployment sub what-if' DEBUG: cli.azure.cli.core.sdk.policies: 'ParameterSetName': '--name --location --template-file --parameter --debug' DEBUG: cli.azure.cli.core.sdk.policies: 'User-Agent': 'AZURECLI/2.56.0 (DEB) azsdk-python-azure-mgmt-resource/23.1.0b2 Python/3.11.5 (Linux-6.2.0-1019-azure-x8664-with-glibc2.35) VSTS[removed]_build_543_0' DEBUG: cli.azure.cli.core.sdk.policies: 'Authorization': '**' DEBUG: cli.azure.cli.core.sdk.policies: Request body: DEBUG: cli.azure.cli.core.sdk.policies: This request has no body DEBUG: urllib3.connectionpool: https://management.azure.com:443 "GET /subscriptions/[removed]/operationresults/[removed]?api-version=2022-09-01&t=638433164467030698&c=[Removed]&s=[removed] HTTP/1.1" 200 383 DEBUG: cli.azure.cli.core.sdk.policies: Response status: 200 DEBUG: cli.azure.cli.core.sdk.policies: Response headers: DEBUG: cli.azure.cli.core.sdk.policies: 'Cache-Control': 'no-cache' DEBUG: cli.azure.cli.core.sdk.policies: 'Pragma': 'no-cache' DEBUG: cli.azure.cli.core.sdk.policies: 'Content-Type': 'application/json; charset=utf-8' DEBUG: cli.azure.cli.core.sdk.policies: 'Expires': '-1' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-ratelimit-remaining-subscription-reads': '11998' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-request-id': 'removed' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-correlation-request-id': 'removed' DEBUG: cli.azure.cli.core.sdk.policies: 'x-ms-routing-request-id': 'WESTEUROPE:20240212T063421Z:removed' DEBUG: cli.azure.cli.core.sdk.policies: 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains' DEBUG: cli.azure.cli.core.sdk.policies: 'X-Content-Type-Options': 'nosniff' DEBUG: cli.azure.cli.core.sdk.policies: 'Date': 'Mon, 12 Feb 2024 06:34:21 GMT' DEBUG: cli.azure.cli.core.sdk.policies: 'Content-Length': '383' DEBUG: cli.azure.cli.core.sdk.policies: Response content: DEBUG: cli.azure.cli.core.sdk.policies: {"status":"Failed","error":{"code":"InternalServerError","message":"Encountered internal server error while processing the deployment what-if request. Diagnostic information: timestamp '20240212T063409Z', scope '/subscriptions/[removed]', tracking id '[removed]', request correlation id '[removed]'."}} DEBUG: cli.azure.cli.core.azclierror: Traceback (most recent call last): File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 697, in _run_job result = cmd_copy(params) ^^^^^^^^^^^^^^^^ File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 333, in call return self.handler(args, kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/command_operation.py", line 121, in handler return op(**command_args) ^^^^^^^^^^^^^^^^^^ File "/opt/az/lib/python3.11/site-packages/azure/cli/command_modules/resource/custom.py", line 936, in what_if_deploy_arm_template_at_subscription_scope return _what_if_deploy_arm_template_at_subscription_scope_core(cmd, ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/opt/az/lib/python3.11/site-packages/azure/cli/command_modules/resource/custom.py", line 956, in _what_if_deploy_arm_template_at_subscription_scope_core what_if_result = _what_if_deploy_arm_template_core(cmd.cli_ctx, what_if_poller, no_pretty_print, exclude_change_types) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/opt/az/lib/python3.11/site-packages/azure/cli/command_modules/resource/custom.py", line 1028, in _what_if_deploy_arm_template_core raise CLIError(err_message) knack.util.CLIError: InternalServerError - Encountered internal server error while processing the deployment what-if request. Diagnostic information: timestamp '20240212T063409Z', scope '/subscriptions/[removed]', tracking id '[removed]', request correlation id '[removed]'.

   During handling of the above exception, another exception occurred:

   Traceback (most recent call last):
     File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/arm.py", line 109, in handle_template_based_exception
       raise CLIError(ex.inner_exception.error.message)
                      ^^^^^^^^^^^^^^^^^^
   AttributeError: 'CLIError' object has no attribute 'inner_exception'

   During handling of the above exception, another exception occurred:

   Traceback (most recent call last):
     File "/opt/az/lib/python3.11/site-packages/knack/cli.py", line 233, in invoke
       cmd_result = self.invocation.execute(args)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
     File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/__init__.py", line 663, in execute
       raise ex
       File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/__init__.py", line 726, in _run_jobs_serially
       results.append(self._run_job(expanded_arg, cmd_copy))
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
     File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/__init__.py", line 718, in _run_job
       return cmd_copy.exception_handler(ex)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
     File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/arm.py", line 114, in handle_template_based_exception
       raise CLIError(ex)
   knack.util.CLIError: InternalServerError - Encountered internal server error while processing the deployment what-if request. Diagnostic information: timestamp '20240212T063409Z', scope '/subscriptions/[removed]', tracking id '[removed]', request correlation id '[removed]'.

   ERROR: cli.azure.cli.core.azclierror: InternalServerError - Encountered internal server error while processing the deployment what-if request. Diagnostic information: timestamp '20240212T063409Z', scope '/subscriptions/[removed]', tracking id '[removed]', request correlation id '[removed]'.
   ERROR: az_command_data_logger: InternalServerError - Encountered internal server error while processing the deployment what-if request. Diagnostic information: timestamp '20240212T063409Z', scope '/subscriptions/[removed]', tracking id '[removed]', request correlation id '[removed]'.
   DEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7f33c2df11c0>]
   INFO: az_command_data_logger: exit code: 1
   INFO: cli.__main__: Command ran in 24.194 seconds (init: 0.183, invoke: 24.011)
   INFO: telemetry.main: Begin splitting cli events and extra events, total events: 1
   INFO: telemetry.client: Accumulated 0 events. Flush the clients.
   INFO: telemetry.main: Finish splitting cli events and extra events, cli events: 1
   INFO: telemetry.save: Save telemetry record of length 3856 in cache
   INFO: telemetry.main: Begin creating telemetry upload process.
   INFO: telemetry.process: Creating upload process: "/opt/az/bin/python3 /opt/az/lib/python3.11/site-packages/azure/cli/telemetry/__init__.py /home/vsts/work/_temp/.azclitask"
   INFO: telemetry.process: Return from creating process
   INFO: telemetry.main: Finish creating telemetry upload process.

Expected behavior

Should see the expected change output of the what-if command

Environment Summary

azure-cli 2.56.0 *

core 2.56.0 * telemetry 1.1.0

Extensions: azure-devops 0.26.0

Dependencies: msal 1.24.0b2 azure-mgmt-resource 23.1.0b2

Python location '/opt/az/bin/python3' Extensions directory '/opt/az/azcliextensions'

Python (Linux) 3.11.5 (main, Jan 8 2024, 09:08:13) [GCC 11.4.0]

Additional context

I have identified this call and module to be the issue:

Call: param keyVaultName string module FunctionKeyVault '../../Resources/KeyVaultModule.bicep' = { name: '${deployment().name}-KeyVault' params: { location: location keyVaultName: keyVaultName
tenantId: '[removed]' } scope: resourceGroup(resourceGroupName) dependsOn: [ [removed]
] }

Module: param keyVaultName string param location string param tenantId string

resource qqq 'Microsoft.KeyVault/vaults@2021-10-01' = { name: keyVaultName location: location properties: { tenantId: tenantId sku: { name: 'standard' family: 'A' } createMode: 'default' } }

azure-client-tools-bot-prd[bot] commented 7 months ago

Hi @cwistedt,

2.56.0 is not the latest Azure CLI(2.57.0).

If you haven't already attempted to do so, please upgrade to the latest Azure CLI version by following https://learn.microsoft.com/en-us/cli/azure/update-azure-cli.

yonzhan commented 7 months ago

Thank you for opening this issue, we will look into it.

cwistedt commented 7 months ago

Nevermind. Found the issue. I called a Module with Within a Module. An both had the same deployment name. What i would have expected is an error saying the deployment name was already taken (like what happens if i have the same deployment name in the same file)

cwistedt commented 7 months ago

Closed