search

Azure / azure-powershell

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

Token not refreshed during long running deployments #13367

Closed filizt closed 4 years ago

filizt commented 4 years ago

Description

Account token not refreshed during long running deployments using deployments cmdlets such as New-AzResourceGroupDeployment. After an hour, we get a 401 as the deployment polls for deployment status and cmdlet throws. This seems to be regression in Az module v 5.0.0.

Steps to reproduce

1) Login using Connect-AzAccount with your credentials 2) Start a deployment using New-AzResourceGroupDeployment with a template that will take more than an hour to deploy (I can provide a template to use, please let me know) 3) After about an hour you'll get a 401 and cmdlet throws

Connect-AzAccount
New-AzResourceGroupDeployment -Name BugRepro -ResourceGroupName filiz-test -TemplateFile .\TakesForeverTemplate.json

Environment data

Name                           Value
----                           -----
PSVersion                      5.1.18362.1110
PSEdition                      Desktop
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
BuildVersion                   10.0.18362.1110
CLRVersion                     4.0.30319.42000
WSManStackVersion              3.0
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1

Module versions

    Directory: C:\Program Files\WindowsPowerShell\Modules

ModuleType Version    Name                                ExportedCommands
---------- -------    ----                                ----------------
Script     2.1.0      Az.Accounts                         {Disable-AzDataCollection, Disable-AzContextAutosave, Enab...
Script     1.1.1      Az.Advisor                          {Get-AzAdvisorRecommendation, Enable-AzAdvisorRecommendati...
Script     2.0.0      Az.Aks                              {Get-AzAksCluster, New-AzAksCluster, Remove-AzAksCluster, ...
Script     1.1.4      Az.AnalysisServices                 {Resume-AzAnalysisServicesServer, Suspend-AzAnalysisServic...
Script     2.1.0      Az.ApiManagement                    {Add-AzApiManagementApiToGateway, Add-AzApiManagementApiTo...
Script     1.1.0      Az.ApplicationInsights              {Get-AzApplicationInsights, New-AzApplicationInsights, Rem...
Script     1.4.0      Az.Automation                       {Get-AzAutomationHybridWorkerGroup, Remove-AzAutomationHyb...
Script     3.1.0      Az.Batch                            {Remove-AzBatchAccount, Get-AzBatchAccount, Get-AzBatchAcc...
Script     2.0.0      Az.Billing                          {Get-AzBillingInvoice, Get-AzBillingPeriod, Get-AzEnrollme...
Script     1.6.0      Az.Cdn                              {Get-AzCdnProfile, Get-AzCdnProfileSsoUrl, New-AzCdnProfil...
Script     1.8.0      Az.CognitiveServices                {Get-AzCognitiveServicesAccount, Get-AzCognitiveServicesAc...
Script     4.6.0      Az.Compute                          {Remove-AzAvailabilitySet, Get-AzAvailabilitySet, New-AzAv...
Script     1.0.3      Az.ContainerInstance                {New-AzContainerGroup, Get-AzContainerGroup, Remove-AzCont...
Script     2.0.0      Az.ContainerRegistry                {New-AzContainerRegistry, Get-AzContainerRegistry, Update-...
Script     1.1.0      Az.DataBoxEdge                      {Get-AzDataBoxEdgeJob, Get-AzDataBoxEdgeDevice, Invoke-AzD...
Script     1.0.1      Az.Databricks                       {Get-AzDatabricksVNetPeering, Get-AzDatabricksWorkspace, N...
Script     1.11.0     Az.DataFactory                      {Set-AzDataFactoryV2, Update-AzDataFactoryV2, Get-AzDataFa...
Script     1.0.2      Az.DataLakeAnalytics                {Get-AzDataLakeAnalyticsDataSource, New-AzDataLakeAnalytic...
Script     1.2.8      Az.DataLakeStore                    {Get-AzDataLakeStoreTrustedIdProvider, Remove-AzDataLakeSt...
Script     1.0.0      Az.DataShare                        {New-AzDataShareAccount, Get-AzDataShareAccount, Remove-Az...
Script     1.1.0      Az.DeploymentManager                {Get-AzDeploymentManagerArtifactSource, New-AzDeploymentMa...
Script     2.0.0      Az.DesktopVirtualization            {Disconnect-AzWvdUserSession, Get-AzWvdApplication, Get-Az...
Script     1.0.2      Az.DevTestLabs                      {Get-AzDtlAllowedVMSizesPolicy, Get-AzDtlAutoShutdownPolic...
Script     1.1.2      Az.Dns                              {Get-AzDnsRecordSet, New-AzDnsRecordConfig, Remove-AzDnsRe...
Script     1.3.0      Az.EventGrid                        {New-AzEventGridTopic, Get-AzEventGridTopic, Set-AzEventGr...
Script     1.7.0      Az.EventHub                         {New-AzEventHubNamespace, Get-AzEventHubNamespace, Set-AzE...
Script     1.6.1      Az.FrontDoor                        {New-AzFrontDoor, Get-AzFrontDoor, Set-AzFrontDoor, Remove...
Script     2.0.0      Az.Functions                        {Get-AzFunctionApp, Get-AzFunctionAppAvailableLocation, Ge...
Script     4.0.0      Az.HDInsight                        {Get-AzHDInsightJob, New-AzHDInsightSqoopJobDefinition, Wa...
Script     1.1.0      Az.HealthcareApis                   {New-AzHealthcareApisService, Remove-AzHealthcareApisServi...
Script     2.6.0      Az.IotHub                           {Add-AzIotHubKey, Get-AzIotHubEventHubConsumerGroup, Get-A...
Script     3.0.0      Az.KeyVault                         {Add-AzManagedHsmKey, Get-AzManagedHsmKey, Remove-AzManage...
Script     1.0.0      Az.Kusto                            {Add-AzKustoClusterLanguageExtension, Add-AzKustoDatabaseP...
Script     1.3.2      Az.LogicApp                         {Get-AzIntegrationAccountAgreement, Get-AzIntegrationAccou...
Script     1.1.3      Az.MachineLearning                  {Move-AzMlCommitmentAssociation, Get-AzMlCommitmentAssocia...
Script     1.1.0      Az.Maintenance                      {Get-AzApplyUpdate, Get-AzConfigurationAssignment, Get-AzM...
Script     2.0.0      Az.ManagedServices                  {Get-AzManagedServicesAssignment, New-AzManagedServicesAss...
Script     1.0.2      Az.MarketplaceOrdering              {Get-AzMarketplaceTerms, Set-AzMarketplaceTerms}
Script     1.1.1      Az.Media                            {Sync-AzMediaServiceStorageKey, Set-AzMediaServiceKey, Get...
Script     2.2.0      Az.Monitor                          {Get-AzMetricDefinition, Get-AzMetric, Remove-AzLogProfile...
Script     4.1.0      Az.Network                          {Add-AzApplicationGatewayAuthenticationCertificate, Get-Az...
Script     1.1.1      Az.NotificationHubs                 {Get-AzNotificationHub, Get-AzNotificationHubAuthorization...
Script     2.3.0      Az.OperationalInsights              {New-AzOperationalInsightsAzureActivityLogDataSource, New-...
Script     1.3.1      Az.PolicyInsights                   {Get-AzPolicyEvent, Get-AzPolicyState, Get-AzPolicyStateSu...
Script     1.1.2      Az.PowerBIEmbedded                  {Remove-AzPowerBIWorkspaceCollection, Get-AzPowerBIWorkspa...
Script     1.0.3      Az.PrivateDns                       {Get-AzPrivateDnsZone, Remove-AzPrivateDnsZone, Set-AzPriv...
Script     3.0.0      Az.RecoveryServices                 {Get-AzRecoveryServicesBackupProperty, Get-AzRecoveryServi...
Script     1.4.0      Az.RedisCache                       {Remove-AzRedisCachePatchSchedule, New-AzRedisCacheSchedul...
Script     1.0.3      Az.Relay                            {New-AzRelayNamespace, Get-AzRelayNamespace, Set-AzRelayNa...
Script     3.0.0      Az.Resources                        {Get-AzProviderOperation, Remove-AzRoleAssignment, Get-AzR...
Script     1.4.1      Az.ServiceBus                       {New-AzServiceBusNamespace, Get-AzServiceBusNamespace, Set...
Script     2.2.0      Az.ServiceFabric                    {Add-AzServiceFabricClientCertificate, Add-AzServiceFabric...
Script     1.2.0      Az.SignalR                          {New-AzSignalR, Get-AzSignalR, Get-AzSignalRKey, New-AzSig...
Script     2.11.1     Az.Sql                              {Get-AzSqlDatabaseTransparentDataEncryption, Get-AzSqlData...
Script     1.1.0      Az.SqlVirtualMachine                {New-AzSqlVM, Get-AzSqlVM, Update-AzSqlVM, Remove-AzSqlVM...}
Script     3.0.0      Az.Storage                          {Get-AzStorageAccount, Get-AzStorageAccountKey, New-AzStor...
Script     1.3.0      Az.StorageSync                      {Invoke-AzStorageSyncCompatibilityCheck, New-AzStorageSync...
Script     1.0.1      Az.StreamAnalytics                  {Get-AzStreamAnalyticsFunction, Get-AzStreamAnalyticsDefau...
Script     1.0.0      Az.Support                          {Get-AzSupportService, Get-AzSupportProblemClassification,...
Script     1.0.4      Az.TrafficManager                   {Add-AzTrafficManagerCustomHeaderToEndpoint, Remove-AzTraf...
Script     2.0.0      Az.Websites                         {Get-AzAppServicePlan, Set-AzAppServicePlan, New-AzAppServ...
Script     1.0.1      Microsoft.PowerShell.Operation.V... {Get-OperationValidation, Invoke-OperationValidation}
Binary     1.0.0.1    PackageManagement                   {Find-Package, Get-Package, Get-PackageProvider, Get-Packa...
Script     3.4.0      Pester                              {Describe, Context, It, Should...}
Script     1.0.0.1    PowerShellGet                       {Install-Module, Find-Module, Save-Module, Update-Module...}
Script     2.0.0      PSReadline                          {Get-PSReadLineKeyHandler, Set-PSReadLineKeyHandler, Remov...

Debug output

Part of the debug output:
        "duration": "PT57M8.5034944S",
        "trackingId": "0f11954a-2c7b-43db-aff3-04a41f205978",
        "serviceRequestId": "50df98b1-e3ce-4c71-94a4-17ac857b1f2b",
        "statusCode": "Created",
        "targetResource": {
          "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
mentScripts/sleep2",
          "resourceType": "Microsoft.Resources/deploymentScripts",
          "resourceName": "sleep2"
        }
      }
    }
  ]
}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/providers
/Microsoft.Resources/deployments/BugRepro5.0?api-version=2020-06-01

Headers:
x-ms-client-request-id        : c8096769-ca06-455f-9d27-9ff39c52d12a
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
Retry-After                   : 16
x-ms-ratelimit-remaining-subscription-reads: 11524
x-ms-request-id               : 4c73de29-6336-48c6-ba8d-746028a3e436
x-ms-correlation-request-id   : 4c73de29-6336-48c6-ba8d-746028a3e436
x-ms-routing-request-id       : WESTUS2:20201030T145739Z:4c73de29-6336-48c6-ba8d-746028a3e436
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:57:38 GMT

Body:
{
  "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0",
  "name": "BugRepro5.0",
  "type": "Microsoft.Resources/deployments",
  "properties": {
    "templateHash": "8930437586655289920",
    "parameters": {
      "userAssignedIdentity": {
        "type": "String",
        "value":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/Ds-TestRg/providers/Microsoft.ManagedIdentity/userA
ssignedIdentities/filiz-user-assigned-msi"
      },
      "newGuid": {
        "type": "String",
        "value": "61b67cdf-56ab-4686-85e9-5a405ccfc1fe"
      }
    },
    "mode": "Incremental",
    "provisioningState": "Running",
    "timestamp": "2020-10-30T14:57:39.1836945Z",
    "duration": "PT57M8.9031208S",
    "correlationId": "50a0d139-bbfb-4b0e-a1f3-3cf22ac9ad60",
    "providers": [
      {
        "namespace": "Microsoft.Resources",
        "resourceTypes": [
          {
            "resourceType": "deploymentScripts",
            "locations": [
              "westus2"
            ]
          }
        ]
      }
    ],
    "dependencies": []
  }
}

VERBOSE: 7:57:39 AM - Checking deployment status in 16 seconds
DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/deploymen
ts/BugRepro5.0/operations?api-version=2020-06-01

Headers:
x-ms-client-request-id        : 25d2efd6-76a9-4416-a7a8-6d02c5fe8695
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
x-ms-ratelimit-remaining-subscription-reads: 11523
x-ms-request-id               : 1dfcfb1d-7620-4749-94c0-c859d072dbfb
x-ms-correlation-request-id   : 1dfcfb1d-7620-4749-94c0-c859d072dbfb
x-ms-routing-request-id       : WESTUS2:20201030T145755Z:1dfcfb1d-7620-4749-94c0-c859d072dbfb
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:57:55 GMT

Body:
{
  "value": [
    {
      "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0/operations/A01584475E86F8F4",
      "operationId": "A01584475E86F8F4",
      "properties": {
        "provisioningOperation": "Create",
        "provisioningState": "Running",
        "timestamp": "2020-10-30T14:57:55.3045655Z",
        "duration": "PT57M24.6027827S",
        "trackingId": "bd058c14-53ec-487e-9fa6-3be63a232deb",
        "serviceRequestId": "50df98b1-e3ce-4c71-94a4-17ac857b1f2b",
        "statusCode": "Created",
        "targetResource": {
          "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
mentScripts/sleep2",
          "resourceType": "Microsoft.Resources/deploymentScripts",
          "resourceName": "sleep2"
        }
      }
    }
  ]
}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/providers
/Microsoft.Resources/deployments/BugRepro5.0?api-version=2020-06-01

Headers:
x-ms-client-request-id        : ffca763f-f10b-4502-b314-6191b698d933
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
Retry-After                   : 16
x-ms-ratelimit-remaining-subscription-reads: 11522
x-ms-request-id               : aa7d1a8b-9055-4d9f-8ebf-1270e54ad819
x-ms-correlation-request-id   : aa7d1a8b-9055-4d9f-8ebf-1270e54ad819
x-ms-routing-request-id       : WESTUS2:20201030T145755Z:aa7d1a8b-9055-4d9f-8ebf-1270e54ad819
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:57:55 GMT

Body:
{
  "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0",
  "name": "BugRepro5.0",
  "type": "Microsoft.Resources/deployments",
  "properties": {
    "templateHash": "8930437586655289920",
    "parameters": {
      "userAssignedIdentity": {
        "type": "String",
        "value":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/Ds-TestRg/providers/Microsoft.ManagedIdentity/userA
ssignedIdentities/filiz-user-assigned-msi"
      },
      "newGuid": {
        "type": "String",
        "value": "61b67cdf-56ab-4686-85e9-5a405ccfc1fe"
      }
    },
    "mode": "Incremental",
    "provisioningState": "Running",
    "timestamp": "2020-10-30T14:57:55.2662599Z",
    "duration": "PT57M24.9856862S",
    "correlationId": "50a0d139-bbfb-4b0e-a1f3-3cf22ac9ad60",
    "providers": [
      {
        "namespace": "Microsoft.Resources",
        "resourceTypes": [
          {
            "resourceType": "deploymentScripts",
            "locations": [
              "westus2"
            ]
          }
        ]
      }
    ],
    "dependencies": []
  }
}

VERBOSE: 7:57:55 AM - Checking deployment status in 16 seconds
DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/deploymen
ts/BugRepro5.0/operations?api-version=2020-06-01

Headers:
x-ms-client-request-id        : e6081bf0-182a-4236-a1cb-fd10cf711f8f
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
x-ms-ratelimit-remaining-subscription-reads: 11521
x-ms-request-id               : 8a4243be-0b78-417e-9d4e-19b3d02a8c89
x-ms-correlation-request-id   : 8a4243be-0b78-417e-9d4e-19b3d02a8c89
x-ms-routing-request-id       : WESTUS2:20201030T145811Z:8a4243be-0b78-417e-9d4e-19b3d02a8c89
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:58:11 GMT

Body:
{
  "value": [
    {
      "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0/operations/A01584475E86F8F4",
      "operationId": "A01584475E86F8F4",
      "properties": {
        "provisioningOperation": "Create",
        "provisioningState": "Running",
        "timestamp": "2020-10-30T14:58:10.8998306Z",
        "duration": "PT57M40.1980478S",
        "trackingId": "1310d8e7-f1c4-4bfa-aaa8-5a372aaf7560",
        "serviceRequestId": "50df98b1-e3ce-4c71-94a4-17ac857b1f2b",
        "statusCode": "Created",
        "targetResource": {
          "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
mentScripts/sleep2",
          "resourceType": "Microsoft.Resources/deploymentScripts",
          "resourceName": "sleep2"
        }
      }
    }
  ]
}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/providers
/Microsoft.Resources/deployments/BugRepro5.0?api-version=2020-06-01

Headers:
x-ms-client-request-id        : 1f42ab09-973e-460a-96df-5cf25d514627
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
Retry-After                   : 15
x-ms-ratelimit-remaining-subscription-reads: 11520
x-ms-request-id               : 8dee334e-7ade-49cc-8bfb-cd69e54229b2
x-ms-correlation-request-id   : 8dee334e-7ade-49cc-8bfb-cd69e54229b2
x-ms-routing-request-id       : WESTUS2:20201030T145811Z:8dee334e-7ade-49cc-8bfb-cd69e54229b2
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:58:11 GMT

Body:
{
  "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0",
  "name": "BugRepro5.0",
  "type": "Microsoft.Resources/deployments",
  "properties": {
    "templateHash": "8930437586655289920",
    "parameters": {
      "userAssignedIdentity": {
        "type": "String",
        "value":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/Ds-TestRg/providers/Microsoft.ManagedIdentity/userA
ssignedIdentities/filiz-user-assigned-msi"
      },
      "newGuid": {
        "type": "String",
        "value": "61b67cdf-56ab-4686-85e9-5a405ccfc1fe"
      }
    },
    "mode": "Incremental",
    "provisioningState": "Running",
    "timestamp": "2020-10-30T14:58:10.8741523Z",
    "duration": "PT57M40.5935786S",
    "correlationId": "50a0d139-bbfb-4b0e-a1f3-3cf22ac9ad60",
    "providers": [
      {
        "namespace": "Microsoft.Resources",
        "resourceTypes": [
          {
            "resourceType": "deploymentScripts",
            "locations": [
              "westus2"
            ]
          }
        ]
      }
    ],
    "dependencies": []
  }
}

VERBOSE: 7:58:12 AM - Checking deployment status in 15 seconds
DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/deploymen
ts/BugRepro5.0/operations?api-version=2020-06-01

Headers:
x-ms-client-request-id        : e6b745a4-a950-42bd-aebc-ab82a6c99d50
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
x-ms-ratelimit-remaining-subscription-reads: 11519
x-ms-request-id               : a962a2e4-dcf0-4b6c-b18e-598fd06e43d5
x-ms-correlation-request-id   : a962a2e4-dcf0-4b6c-b18e-598fd06e43d5
x-ms-routing-request-id       : WESTUS2:20201030T145827Z:a962a2e4-dcf0-4b6c-b18e-598fd06e43d5
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:58:26 GMT

Body:
{
  "value": [
    {
      "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0/operations/A01584475E86F8F4",
      "operationId": "A01584475E86F8F4",
      "properties": {
        "provisioningOperation": "Create",
        "provisioningState": "Running",
        "timestamp": "2020-10-30T14:58:26.0845544Z",
        "duration": "PT57M55.3827716S",
        "trackingId": "22d76184-f089-484d-9457-fcc656b54ea3",
        "serviceRequestId": "50df98b1-e3ce-4c71-94a4-17ac857b1f2b",
        "statusCode": "Created",
        "targetResource": {
          "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
mentScripts/sleep2",
          "resourceType": "Microsoft.Resources/deploymentScripts",
          "resourceName": "sleep2"
        }
      }
    }
  ]
}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/providers
/Microsoft.Resources/deployments/BugRepro5.0?api-version=2020-06-01

Headers:
x-ms-client-request-id        : cc59d860-35db-4bd0-a4f6-78080dccd1f8
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
Retry-After                   : 15
x-ms-ratelimit-remaining-subscription-reads: 11518
x-ms-request-id               : 2e7d61d7-f1af-4f8d-9797-a00df33c1e84
x-ms-correlation-request-id   : 2e7d61d7-f1af-4f8d-9797-a00df33c1e84
x-ms-routing-request-id       : WESTUS2:20201030T145827Z:2e7d61d7-f1af-4f8d-9797-a00df33c1e84
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:58:26 GMT

Body:
{
  "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0",
  "name": "BugRepro5.0",
  "type": "Microsoft.Resources/deployments",
  "properties": {
    "templateHash": "8930437586655289920",
    "parameters": {
      "userAssignedIdentity": {
        "type": "String",
        "value":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/Ds-TestRg/providers/Microsoft.ManagedIdentity/userA
ssignedIdentities/filiz-user-assigned-msi"
      },
      "newGuid": {
        "type": "String",
        "value": "61b67cdf-56ab-4686-85e9-5a405ccfc1fe"
      }
    },
    "mode": "Incremental",
    "provisioningState": "Running",
    "timestamp": "2020-10-30T14:58:26.0547248Z",
    "duration": "PT57M55.7741511S",
    "correlationId": "50a0d139-bbfb-4b0e-a1f3-3cf22ac9ad60",
    "providers": [
      {
        "namespace": "Microsoft.Resources",
        "resourceTypes": [
          {
            "resourceType": "deploymentScripts",
            "locations": [
              "westus2"
            ]
          }
        ]
      }
    ],
    "dependencies": []
  }
}

VERBOSE: 7:58:27 AM - Checking deployment status in 15 seconds
DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/deploymen
ts/BugRepro5.0/operations?api-version=2020-06-01

Headers:
x-ms-client-request-id        : 80632692-7370-4e96-8839-b306be402f60
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
x-ms-ratelimit-remaining-subscription-reads: 11517
x-ms-request-id               : 88a480bf-8fbc-497a-9f5d-d8b7820a95c7
x-ms-correlation-request-id   : 88a480bf-8fbc-497a-9f5d-d8b7820a95c7
x-ms-routing-request-id       : WESTUS2:20201030T145842Z:88a480bf-8fbc-497a-9f5d-d8b7820a95c7
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:58:41 GMT

Body:
{
  "value": [
    {
      "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0/operations/A01584475E86F8F4",
      "operationId": "A01584475E86F8F4",
      "properties": {
        "provisioningOperation": "Create",
        "provisioningState": "Running",
        "timestamp": "2020-10-30T14:58:41.2718384Z",
        "duration": "PT58M10.5700556S",
        "trackingId": "26d303b9-bfc2-41ee-b208-f3905f1853c3",
        "serviceRequestId": "50df98b1-e3ce-4c71-94a4-17ac857b1f2b",
        "statusCode": "Created",
        "targetResource": {
          "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
mentScripts/sleep2",
          "resourceType": "Microsoft.Resources/deploymentScripts",
          "resourceName": "sleep2"
        }
      }
    }
  ]
}

DEBUG: ============================ HTTP REQUEST ============================

HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/providers
/Microsoft.Resources/deployments/BugRepro5.0?api-version=2020-06-01

Headers:
x-ms-client-request-id        : 19bc19f5-e7e2-4bbb-8053-a7bc6e08e70d
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
OK

Headers:
Pragma                        : no-cache
Retry-After                   : 15
x-ms-ratelimit-remaining-subscription-reads: 11516
x-ms-request-id               : cd53ab48-bb7d-48db-a4f1-787a39ea7649
x-ms-correlation-request-id   : cd53ab48-bb7d-48db-a4f1-787a39ea7649
x-ms-routing-request-id       : WESTUS2:20201030T145842Z:cd53ab48-bb7d-48db-a4f1-787a39ea7649
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:58:41 GMT

Body:
{
  "id":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/filiz-test-001/providers/Microsoft.Resources/deploy
ments/BugRepro5.0",
  "name": "BugRepro5.0",
  "type": "Microsoft.Resources/deployments",
  "properties": {
    "templateHash": "8930437586655289920",
    "parameters": {
      "userAssignedIdentity": {
        "type": "String",
        "value":
"/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourceGroups/Ds-TestRg/providers/Microsoft.ManagedIdentity/userA
ssignedIdentities/filiz-user-assigned-msi"
      },
      "newGuid": {
        "type": "String",
        "value": "61b67cdf-56ab-4686-85e9-5a405ccfc1fe"
      }
    },
    "mode": "Incremental",
    "provisioningState": "Running",
    "timestamp": "2020-10-30T14:58:41.2471187Z",
    "duration": "PT58M10.966545S",
    "correlationId": "50a0d139-bbfb-4b0e-a1f3-3cf22ac9ad60",
    "providers": [
      {
        "namespace": "Microsoft.Resources",
        "resourceTypes": [
          {
            "resourceType": "deploymentScripts",
            "locations": [
              "westus2"
            ]
          }
        ]
      }
    ],
    "dependencies": []
  }
}

VERBOSE: 7:58:42 AM - Checking deployment status in 15 seconds
DEBUG: ============================ HTTP REQUEST ============================
HTTP Method:
GET

Absolute Uri:
https://management.azure.com/subscriptions/a1bfa635-f2bf-42f1-86b5-848c674fc321/resourcegroups/filiz-test-001/deploymen
ts/BugRepro5.0/operations?api-version=2020-06-01

Headers:
x-ms-client-request-id        : 9b1f5bff-e407-4d60-8792-d48e22ca0bc8
accept-language               : en-US

Body:

DEBUG: ============================ HTTP RESPONSE ============================

Status Code:
Unauthorized

Headers:
Pragma                        : no-cache
x-ms-failure-cause            : gateway
x-ms-request-id               : 5791219d-529e-4167-8e49-6433c164de76
x-ms-correlation-request-id   : 5791219d-529e-4167-8e49-6433c164de76
x-ms-routing-request-id       : WESTUS2:20201030T145857Z:5791219d-529e-4167-8e49-6433c164de76
Strict-Transport-Security     : max-age=31536000; includeSubDomains
X-Content-Type-Options        : nosniff
Connection                    : close
Cache-Control                 : no-cache
Date                          : Fri, 30 Oct 2020 14:58:56 GMT
WWW-Authenticate              : Bearer
authorization_uri="https://login.windows.net/72f988bf-86f1-41af-91ab-2d7cd011db47", error="invalid_token",
error_description="The access token has expired."

Body:
{
  "error": {
    "code": "ExpiredAuthenticationToken",
    "message": "The access token expiry UTC time '10/30/2020 2:58:51 PM' is earlier than current UTC time '10/30/2020
2:58:57 PM'."
  }
}

Confirm
The access token expiry UTC time '10/30/2020 2:58:51 PM' is earlier than current UTC time '10/30/2020 2:58:57 PM'.
StatusCode: 401
ReasonPhrase: Unauthorized
OperationID : 5791219d-529e-4167-8e49-6433c164de76
New-AzResourceGroupDeployment : The access token expiry UTC time '10/30/2020 2:58:51 PM' is earlier than current UTC
time '10/30/2020 2:58:57 PM'.
StatusCode: 401
ReasonPhrase: Unauthorized
OperationID : 5791219d-529e-4167-8e49-6433c164de76
At line:1 char:1
+ New-AzResourceGroupDeployment -Name BugRepro5.0 -ResourceGroupName fi ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : CloseError: (:) [New-AzResourceGroupDeployment], ResourceManagerCloudException
    + FullyQualifiedErrorId : Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.NewAzureResourceGroupDep
   loymentCmdlet

DEBUG: AzureQoSEvent: CommandName - New-AzResourceGroupDeployment; IsSuccess - False; Duration - 01:05:40.0439315;;
Exception - Microsoft.Azure.Commands.ResourceManager.Cmdlets.SdkClient.ResourceManagerCloudException: The access token
expiry UTC time '10/30/2020 2:58:51 PM' is earlier than current UTC time '10/30/2020 2:58:57 PM'.
StatusCode: 401
ReasonPhrase: Unauthorized
OperationID : 5791219d-529e-4167-8e49-6433c164de76 ---> Microsoft.Rest.Azure.CloudException: The access token expiry
UTC time '10/30/2020 2:58:51 PM' is earlier than current UTC time '10/30/2020 2:58:57 PM'.
   at Microsoft.Azure.Management.ResourceManager.DeploymentOperations.<ListWithHttpMessagesAsync>d__14.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Azure.Management.ResourceManager.DeploymentOperationsExtensions.<ListAsync>d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Azure.Management.ResourceManager.DeploymentOperationsExtensions.List(IDeploymentOperations operations,
String resourceGroupName, String deploymentName, Nullable`1 top)
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.SdkClient.ResourceManagerSdkClient.ListDeploymentOperations(PSDeployme
ntCmdletParameters parameters)
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.SdkClient.ResourceManagerSdkClient.WriteDeploymentProgress(PSDeploymen
tCmdletParameters parameters, Deployment deployment, DeploymentOperationErrorInfo deploymentOperationError)
   at Microsoft.Azure.Commands.ResourceManager.Cmdlets.SdkClient.ResourceManagerSdkClient.WaitDeploymentStatus(Func`1
getDeployment, Action listDeploymentOperations, ProvisioningState[] status)
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.SdkClient.ResourceManagerSdkClient.ProvisionDeploymentStatus(PSDeploym
entCmdletParameters parameters, Deployment deployment)
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.SdkClient.ResourceManagerSdkClient.ExecuteDeploymentInternal(PSDeploym
entCmdletParameters parameters)
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.SdkClient.ResourceManagerSdkClient.ExecuteResourceGroupDeployment(PSDe
ploymentCmdletParameters parameters)
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.CmdletBase.DeploymentCreateCmdlet.ExecuteDeployment()
   at Microsoft.WindowsAzure.Commands.Utilities.Common.AzurePSCmdlet.ConfirmAction(Boolean force, String
continueMessage, String processMessage, String target, Action action, Func`1 useShouldContinue)
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.NewAzureResourceGroupDeploymentCmdlet.OnProcessRecord()

   at Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.ResourceManagerCmdletBase.ExecuteCmdlet()
   --- End of inner exception stack trace ---
   at
Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.ResourceManagerCmdletBase.HandleException(ExceptionDisp
atchInfo capturedException)
   at Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.ResourceManagerCmdletBase.ExecuteCmdlet()
   at Microsoft.WindowsAzure.Commands.Utilities.Common.AzurePSCmdlet.ProcessRecord();
DEBUG: Finish sending metric.
DEBUG: 8:05:58 AM - NewAzureResourceGroupDeploymentCmdlet end processing.

Error output

equestId      :
Message        : The access token expiry UTC time '10/30/2020 2:58:51 PM' is earlier than current UTC time '10/30/2020
                 2:58:57 PM'.
                 StatusCode: 401
                 ReasonPhrase: Unauthorized
                 OperationID : 5791219d-529e-4167-8e49-6433c164de76
ServerMessage  :
ServerResponse :
RequestMessage :
InvocationInfo : {New-AzResourceGroupDeployment}
Line           : New-AzResourceGroupDeployment -Name BugRepro5.0 -ResourceGroupName filiz-test-001 -TemplateFile
                 C:\Workspace_Laptop\Templates\TemplateTakesForever.json -Debug
Position       : At line:1 char:1
                 + New-AzResourceGroupDeployment -Name BugRepro5.0 -ResourceGroupName fi ...
                 + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
StackTrace     :    at Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.ResourceManagerCmdletBase.Handle
                 Exception(ExceptionDispatchInfo capturedException)
                    at Microsoft.Azure.Commands.ResourceManager.Cmdlets.Implementation.ResourceManagerCmdletBase.Execut
                 eCmdlet()
                    at Microsoft.WindowsAzure.Commands.Utilities.Common.AzurePSCmdlet.ProcessRecord()
HistoryId      : 6

   HistoryId: -1

Message        : Unable to find type [System.Net.Http.HttpClient].
StackTrace     :    at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext
                 funcContext, Exception exception)
                    at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)
                    at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame
                 frame)
                    at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame
                 frame)
Exception      : System.Management.Automation.RuntimeException
InvocationInfo : {}
Line           :         [System.Net.Http.HttpClient]

Position       : At C:\Program Files\WindowsPowerShell\Modules\PowerShellGet\1.0.0.1\PSModule.psm1:6260 char:9
                 +         [System.Net.Http.HttpClient]
                 +         ~~~~~~~~~~~~~~~~~~~~~~~~~~~~
HistoryId      : -1

Message        : Unable to find type [System.Net.Http.HttpClient].
StackTrace     :    at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext
                 funcContext, Exception exception)
                    at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)
                    at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame
                 frame)
                    at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame
                 frame)
Exception      : System.Management.Automation.RuntimeException
InvocationInfo : {}
Line           :         [System.Net.Http.HttpClient]

Position       : At C:\Program Files\WindowsPowerShell\Modules\PowerShellGet\1.0.0.1\PSModule.psm1:6260 char:9
                 +         [System.Net.Http.HttpClient]
                 +         ~~~~~~~~~~~~~~~~~~~~~~~~~~~~
HistoryId      : -1

Message        : Unable to find type [Microsoft.PowerShell.Commands.PowerShellGet.Telemetry].
StackTrace     :    at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext
                 funcContext, Exception exception)
                    at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)
                    at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame
                 frame)
                    at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame
                 frame)
Exception      : System.Management.Automation.RuntimeException
InvocationInfo : {}
Line           :     $telemetryMethods = ([Microsoft.PowerShell.Commands.PowerShellGet.Telemetry] | Get-Member
                 -Static).Name

Position       : At C:\Program Files\WindowsPowerShell\Modules\PowerShellGet\1.0.0.1\PSModule.psm1:715 char:26
                 + ... yMethods = ([Microsoft.PowerShell.Commands.PowerShellGet.Telemetry] | ...
                 +                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
HistoryId      : -1

The Azure PowerShell team is listening, please let us know how we are doing: https://aka.ms/azpssurvey?Q_CHL=ERROR.
erich-wang commented 4 years ago

@filizt , thanks for reporting the issue. Could you please share your template that takes more than hour to complete?

erich-wang commented 4 years ago

@filizt , the issue has been addressed in Az.Accounts 2.1.2, could you please have a try?

filizt commented 4 years ago

@filizt , the issue has been addressed in Az.Accounts 2.1.2, could you please have a try?

Thanks, @erich-wang. I'll test the scenario today.

filizt commented 4 years ago

@erich-wang I tested the new Az.Accounts module and the issue has been fixed. Thanks!

erich-wang commented 4 years ago

Closed this issue as it has been fixed in 2.1.2