Azure / azure-powershell

Microsoft Azure PowerShell
Other
4.26k stars 3.86k forks source link

Azure PowerShell: Falsely Fails Deployments with error "New-AzResourceGroupDeployment: Object reference not set to an instance of an object." #24344

Open Faustish opened 8 months ago

Faustish commented 8 months ago

Description

Azure PowerShell (PowerShell Module AZ) fails deployments with the vague error: "New-AzResourceGroupDeployment: Object reference not set to an instance of an object." while de-facto the resources get deployed in Azure.

PowerShell states that the deployment fails, the resources DO get deployed successfully: Using the same template and parameters from the pipelines when run manually (locally) causes the same failure.

Here are the commands used for Azure PowerShell Deployment: Set-AzContext -SubscriptionId ****----** -TenantId ****---**-*****

New-AzResourceGroupDeployment -TemplateFile .\template.json -TemplateParameterFile .\parameters.json -ResourceGroupName ----bff-rg -SkipTemplateParameterPrompt -Debug -DeploymentDebugLogLevel All

When run with AzureCLI the deployment succeeds without any issues. Here are the commands used for AzureCLI Deployment:

az account set --subscription ****----**

az deployment group create --name **-test-01 --resource-group ----bff-rg --template-file .\template.json --parameters .\parameters.json

Details:

PowerShell “Az” module versions where the bug manifests: 9.3.0 11.2.0 11.3.1

What-If deployments succeed both manually and in the pipelines.

AzureCLI (az) works, and does not cause any issues.

Tested with Bicep-Modules and Templates that contain User Defined Types and without in order to disqualify a recent bug that could have caused this.

Bug was discovered when updating a pipeline to use a new Bicep-Template Tag.

PS: Due to sensitive information a lot of output can't be placed in this report. Resources created in the template is an ASP with autoscale settings, app service, deployment slots, private endpoints and site configs, Consider this a general question to see if any in the community has had the same issue with the general information supplied, please let me know if any other information is required.

Issue script & Debug output

**********************
PowerShell transcript start
Start time: 20240308122533
Username: ***\***
RunAs User: ***\***
Configuration Name: 
Machine: **-**-e2-07-01 (Microsoft Windows NT 10.0.19045.0)
Host Application: C:\Program Files (x86)\PowerShell\7\pwsh.dll -WorkingDirectory ~
Process ID: 20876
PSVersion: 7.2.3
PSEdition: Core
GitCommitId: 7.2.3
OS: Microsoft Windows 10.0.19045
Platform: Win32NT
PSCompatibleVersions: 1.0, 2.0, 3.0, 4.0, 5.0, 5.1.10032.0, 6.0.0, 6.1.0, 6.2.0, 7.0.0, 7.1.0, 7.2.3
PSRemotingProtocolVersion: 2.3
SerializationVersion: 1.1.0.1
WSManStackVersion: 3.0
**********************
Transcript started, output file is .\PowershellSession.log
PS C:\***\***\projects\***> New-AzResourceGroupDeployment -TemplateFile .\template.json -TemplateParameterFile .\parameters.json -ResourceGroupName **-***-**-d-bff-rg -Debug -DeploymentDebugLogLevel All
DEBUG: Initializing ConditionalAssemblyContext. PSEdition is [Core]. PSVersion is [7.2.3].
DEBUG: Initializing ConditionalAssemblyProvider. AssemblyRootPath is [C:\***\***\Documents\PowerShell\Modules\Az.Accounts\2.15.1\StartupScripts\..\lib].
DEBUG: Registering Az shared AssemblyLoadContext.
DEBUG: AssemblyLoadContext registered.
DEBUG: Got version 0 of Az
DEBUG: Got version 0 of Az.Accounts
DEBUG: 12:25:56 - NewAzureResourceGroupDeploymentCmdlet begin processing with ParameterSet 'ByTemplateFileAndParameterFile'.
DEBUG: 12:25:56 - using account id '****@***.com'...
DEBUG: 12:25:56 - [ConfigManager] Got nothing from [DisplayBreakingChangeWarning], Module = [], Cmdlet = []. Returning default value [True].
Confirm
Are you sure you want to perform this action?
Performing the operation "Creating Deployment" on target "**-**-***-bff-rg".
&Yes  Yes to &All  &No  No to A&ll  &Suspend
A
WARNING: The DeploymentDebug setting has been enabled. This can potentially log secrets like passwords used in resource property or listKeys operations when you retrieve the deployment operations through Get-AzResourceGroupDeploymentOperation
Confirm
Continue with this operation?
&Yes  Yes to &All  &Halt Command  &Suspend
A
DEBUG: [Common.Authentication]: Authenticating using Account: '***@***.com', environment: '*****', tenant: '***-***-***-******-****'
DEBUG: 12:26:01 - [ConfigManager] Got nothing from [EnableLoginByWam], Module = [], Cmdlet = []. Returning default value [False].
DEBUG: 12:26:01 - [SilentAuthenticator] Calling SharedTokenCacheCredential.GetTokenAsync - TenantId:'***-***-***-******-****', Scopes:'https://management.core.windows.net//.default', AuthorityHost:'https://login.microsoftonline.com/', UserId:'***@***.com'
DEBUG: SharedTokenCacheCredential.GetToken invoked. Scopes: [ https://management.core.windows.net//.default ] ParentRequestId:
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] IsLegacyAdalCacheEnabled: yes
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] [Region discovery] Not using a regional authority.
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] [Region discovery] Not using a regional authority.
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] IsLegacyAdalCacheEnabled: yes
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] IsLegacyAdalCacheEnabled: yes
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z] Found 1 cache accounts and 0 broker accounts
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z] Returning 1 accounts
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] MSAL MSAL.CoreCLR with assembly version '4.56.0.0'. CorrelationId(1fe3c00f-e894-4e1c-818e-e26714e091b4)
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] === AcquireTokenSilent Parameters ===
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] LoginHint provided: False
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] Account provided: True
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] ForceRefresh: False
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] 
=== Request Data ===
Authority Provided? - True
Scopes - https://management.core.windows.net//.default
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - 1fe3c00f-e894-4e1c-818e-e26714e091b4
UserAssertion set: False
LongRunningOboCacheKey set: False
Region configured:
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] === Token Acquisition (SilentRequest) started:
     Scopes: https://management.core.windows.net//.default
    Authority Host: login.microsoftonline.com
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] [Region discovery] Not using a regional authority.
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] Access token is not expired. Returning the found cache entry. [Current time (03/08/2024 11:26:01) - Expiration Time (03/08/2024 12:29:20 +00:00) - Extended Expiration Time (03/08/2024 12:29:20 +00:00)]
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - 1fe3c00f-e894-4e1c-818e-e26714e091b4] Returning access token found in cache. RefreshOn exists ? False
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - 1fe3c00f-e894-4e1c-818e-e26714e091b4] [Region discovery] Not using a regional authority.
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********] 
    === Token Acquisition finished successfully:
DEBUG: False MSAL 4.56.0.0 MSAL.CoreCLR .NET 6.0.4 Microsoft Windows 10.0.19045 [2024-03-08 11:26:01Z - *********-****-****-****-*********]  AT expiration time: 08.03.2024 12:29:20 +00:00, scopes: https://management.core.windows.net//user_impersonation https://management.core.windows.net//.default. source: Cache
DEBUG: SharedTokenCacheCredential.GetToken succeeded. Scopes: [ https://management.core.windows.net//.default ] ParentRequestId:  ExpiresOn: 2024-03-08T12:29:20.0000000+00:00
DEBUG: [Common.Authentication]: Received token with LoginType 'User', Tenant: '*********-****-****-****-*********', UserId: '****@****.com'
DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
POST

Absolute Uri:
https://management.azure.com/subscriptions/*********-****-****-****-*********/resourcegroups/**-****-**-**-rg/providers/Microsoft.Resources/deployments/template/validate?api-version=2022-09-01

Headers:
x-ms-client-request-id        : 414d10d9-f58b-497d-9b12-81a6ae5d0de6
Accept-Language               : en-US

Body:
{
  "properties": {
    "template": {
      "$schema": "https://schema.management.azure.com/schemas/2019-04-01/deploymentTemplate.json#",
      "languageVersion": "2.0",
      "contentVersion": "1.0.0.0",
      "parameters": {
        "parLocation": {
          "defaultValue": "[resourceGroup().location]",
          "type": "String",
          "metadata": {
            "description": "Location for all resources."
          }
        },
        "parBaseTime": {
          "defaultValue": "[utcNow()]",
          "type": "String",
          "metadata": {
            "description": "Do not change. Used to tag the deployment with the current date. **Default: utcNow('d')**"
          }
        },
        "parResourceTags": {
          "nullable": true,
          "type": "Object",
          "metadata": {
            "description": "Tags of the resource."
          }
        },
        "parInstanceNumber": {
          "minLength": 2,
          "maxLength": 2,
          "type": "String",
          "metadata": {
            "description": "Specifies the instance number for the network security group."
          }
        },
        "parServerOS": {
          "allowedValues": [
            "Windows",
            "Linux"
          ],

...

DEBUG: 12:27:47 - [ConfigManager] Got nothing from [DisableErrorRecordsPersistence], Module = [], Cmdlet = []. Returning default value [False].
DEBUG: 12:27:48 - [ConfigManager] Got [True] from [EnableDataCollection], Module = [], Cmdlet = [].

New-AzResourceGroupDeployment: Object reference not set to an instance of an object.

New-AzResourceGroupDeployment: Object reference not set to an instance of an object.
DEBUG: 12:27:51 - [ConfigManager] Got nothing from [DisplayBreakingChangeWarning], Module = [], Cmdlet = []. Returning default value [True].
DEBUG: 12:27:51 - [ConfigManager] Got nothing from [DisplayRegionIdentified], Module = [], Cmdlet = []. Returning default value [True].
DEBUG: 12:27:51 - [ConfigManager] Got nothing from [CheckForUpgrade], Module = [], Cmdlet = []. Returning default value [True].
DEBUG: AzureQoSEvent:  Module: Az.Resources:6.15.1; CommandName: New-AzResourceGroupDeployment; PSVersion: 7.2.3; IsSuccess: False; Duration: 00:01:52.1577379; Exception: Object reference not set to an instance of an object.;
DEBUG: 12:27:51 - NewAzureResourceGroupDeploymentCmdlet end processing.

Environment data

PS C:\Users\****\projects\****> $PSVersionTable

Name                           Value
----                           -----
PSVersion                      7.2.3
PSEdition                      Core
GitCommitId                    7.2.3
OS                             Microsoft Windows 10.0.19045
Platform                       Win32NT
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

Module versions

PS C:\Users\*****\projects\******> Get-InstalledModule -Name Az -AllVersions | select Name,Version

Name Version
---- -------
Az   11.3.1

Error output

No response

anthony-c-martin commented 8 months ago

This looks like it may be the issue fixed with #24174.

@Faustish - from the logs I see you're using Az.Resources:6.15.1. Please could you try upgrading to the latest release (6.16.0), and confirming whether this fixes the problem?

Faustish commented 7 months ago

Hey all, thanks for the feedback.

I've tested the same deployment now, manually with Az.Resources:6.16.0, and the same issue persists. Both when deploying initially and also when re-running the same deployment. Even when the resources are created, and re-ran the only feedback I get is the infamous "Object reference not set to..."

Faustish commented 6 months ago

Hey again,

Are there any other possible fixes we can try for this issue? Or any other information you guys need to troubleshoot this further?

anthony-c-martin commented 6 months ago

@Faustish - would you mind testing this again with the -Debug flag set, and sharing the logs? I added logging in a recent change to include more information about the source of the error.

Faustish commented 6 months ago

@anthony-c-martin

I'm currently testing this and will update the thread soon.

Testing locally resulted in a working deployment without error this time, but testing through pipeline gave the same error.

Trying to replicate the error locally again, suspecting there was a mistake in generating the error.

Will update in some days due to vacation.