Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

terraform plan hangs forever after trying to upgrade provider to 1.37.0 #4986

Closed
guitmz opened this issue Nov 26, 2019 · 23 comments
Closed

terraform plan hangs forever after trying to upgrade provider to 1.37.0 #4986

guitmz opened this issue Nov 26, 2019 · 23 comments

Comments

@guitmz
Copy link

guitmz commented Nov 26, 2019

Terraform (and AzureRM Provider) Version

  • terraform 0.12.10
  • azurerm 1.37.0

Affected Resource(s)

Not sure what to include here apart from this (mentioned in the logs):

  • azurerm_storage_container
  • azurerm_storage_account

Terraform Configuration Files

resource "azurerm_storage_account" "terraforminfra" {
  name                     = "${replace(var.domain, "-", "")}infra"
  resource_group_name      = azurerm_resource_group.main.name
  location                 = var.region
  account_tier             = "Standard"
  account_replication_type = "ZRS"

  tags = {
    environment = var.domain
  }
}

resource "azurerm_storage_container" "terraform-state" {
  name                  = var.terraform_storage_container_name
  storage_account_name  = azurerm_storage_account.terraforminfra.name
  container_access_type = "private"
}

Debug Output

This just repeats forever

2019/11/26 13:46:35 [TRACE] dag/walk: vertex "provider.azurerm (close)" is waiting for "azurerm_storage_container.terraform-state"
2019/11/26 13:46:36 [TRACE] dag/walk: vertex "azurerm_storage_container.terraform-state" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:36 [TRACE] dag/walk: vertex "output.storage_account_id" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:36 [TRACE] dag/walk: vertex "root" is waiting for "provider.azurerm (close)"
2019/11/26 13:46:40 [TRACE] dag/walk: vertex "provider.azurerm (close)" is waiting for "azurerm_storage_container.terraform-state"
2019/11/26 13:46:41 [TRACE] dag/walk: vertex "azurerm_storage_container.terraform-state" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:41 [TRACE] dag/walk: vertex "output.storage_account_id" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:41 [TRACE] dag/walk: vertex "root" is waiting for "provider.azurerm (close)"
2019/11/26 13:46:45 [TRACE] dag/walk: vertex "provider.azurerm (close)" is waiting for "azurerm_storage_container.terraform-state"
2019/11/26 13:46:46 [TRACE] dag/walk: vertex "azurerm_storage_container.terraform-state" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:46 [TRACE] dag/walk: vertex "output.storage_account_id" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:46 [TRACE] dag/walk: vertex "root" is waiting for "provider.azurerm (close)"
2019/11/26 13:46:50 [TRACE] dag/walk: vertex "provider.azurerm (close)" is waiting for "azurerm_storage_container.terraform-state"
2019/11/26 13:46:51 [TRACE] dag/walk: vertex "output.storage_account_id" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:51 [TRACE] dag/walk: vertex "azurerm_storage_container.terraform-state" is waiting for "azurerm_storage_account.terraforminfra"
2019/11/26 13:46:51 [TRACE] dag/walk: vertex "root" is waiting for "provider.azurerm (close)"

Expected Behavior

Terraform plan should work, upgrade provider, apply necessary changes, etc. Works fine with 1.36.0

Actual Behavior

At some point, terraform plan just hangs forever with the above output, had to enable trace logs to be able to see it

Steps to Reproduce

  1. Update provider to 1.37.0
  2. Run terraform plan
@alex-goncharov
Copy link
Contributor

alex-goncharov commented Nov 27, 2019

I see the same behavior on storage_account resource, it actually manages to come out of this after some 20 minutes.

`
$ TF_LOG=TRACE terraform plan --target module.tfe.module.data.azurerm_storage_account.this
...
2019-11-27T09:02:29.498+0100 [DEBUG] plugin.terraform-provider-azurerm_v1.37.0_x4: POST /subscriptions/XXX/resourceGroups/XXX/providers/Microsoft.Storage/storageAccounts/XXX/listKeys?%24expand=kerb&api-version=2019-04-01 HTTP/1.1
...

2019-11-27T09:02:29.648+0100 [DEBUG] plugin.terraform-provider-azurerm_v1.37.0_x4: [DEBUG] AzureRM Response for https://management.azure.com/subscriptions/XXX/resourceGroups/XXX/providers/Microsoft.Storage/storageAccounts/XXX/listKeys?%24expand=kerb&api-version=2019-04-01:
2019-11-27T09:02:29.648+0100 [DEBUG] plugin.terraform-provider-azurerm_v1.37.0_x4: HTTP/2.0 200 OK
2019-11-27T09:02:29.648+0100 [DEBUG] plugin.terraform-provider-azurerm_v1.37.0_x4: {"keys":[{"keyName":"key1","value":"XXX","permissions":"FULL"},{"keyName":"key2","value":"XXX","permissions":"FULL"}]}

...
2019/11/27 09:23:57 [TRACE] dag/walk: vertex "provider.azurerm.fxi_production1_services (close)" is waiting for "module.tfe.module.data.azurerm_storage_account.this"
2019/11/27 09:23:59 [TRACE] dag/walk: vertex "root" is waiting for "provider.azurerm.fxi_production1_services (close)"
2019/11/27 09:24:02 [TRACE] dag/walk: vertex "provider.azurerm.fxi_production1_services (close)" is waiting for "module.tfe.module.data.azurerm_storage_account.this"
2019/11/27 09:24:04 [TRACE] dag/walk: vertex "root" is waiting for "provider.azurerm.fxi_production1_services (close)"
2019/11/27 09:24:04 [TRACE] module.tfe.module.data: eval: *terraform.EvalWriteState
2019/11/27 09:24:04 [TRACE] EvalWriteState: recording 1 dependencies for module.tfe.module.data.azurerm_storage_account.this
2019/11/27 09:24:04 [TRACE] EvalWriteState: writing current state object for module.tfe.module.data.azurerm_storage_account.this
2019/11/27 09:24:04 [TRACE] [walkRefresh] Exiting eval tree: module.tfe.module.data.azurerm_storage_account.this
2019/11/27 09:24:04 [TRACE] vertex "module.tfe.module.data.azurerm_storage_account.this": visit complete
2019/11/27 09:24:04 [TRACE] vertex "module.tfe.module.data.azurerm_storage_account.this": dynamic subgraph completed successfully
2019/11/27 09:24:04 [TRACE] vertex "module.tfe.module.data.azurerm_storage_account.this": visit complete
`

@alex-goncharov
Copy link
Contributor

alex-goncharov commented Nov 28, 2019

The delay is caused by this call https://github.com/terraform-providers/terraform-provider-azurerm/blob/6ed5554bad427aae8872c6ead28b53844b209aa5/azurerm/resource_arm_storage_account.go#L1164.

This eventually calls the code from github.com/Azure/go-autorest/autorest v0.9.2, which was upgraded from 0.9.0 in 1.37.0 release:

$ git diff v1.36.1 v1.37.0 go.mod
diff --git a/go.mod b/go.mod
index 05c0f84a5..97df6065b 100644
--- a/go.mod
+++ b/go.mod
@@ -1,13 +1,13 @@
 module github.com/terraform-providers/terraform-provider-azurerm

 require (
-       github.com/Azure/azure-sdk-for-go v34.1.0+incompatible
-       github.com/Azure/go-autorest/autorest v0.9.0
+       github.com/Azure/azure-sdk-for-go v36.2.0+incompatible
+       github.com/Azure/go-autorest/autorest v0.9.2

@alex-goncharov
Copy link
Contributor

alex-goncharov commented Nov 28, 2019

the delay is introduced in https://github.com/Azure/go-autorest/blob/master/autorest/sender.go

$ git diff autorest/v0.9.0 autorest/v0.9.2 sender.go
diff --git a/autorest/sender.go b/autorest/sender.go
index e582489..5e595d7 100644
--- a/autorest/sender.go
+++ b/autorest/sender.go
@@ -289,10 +289,6 @@ func doRetryForStatusCodesImpl(s Sender, r *http.Request, count429 bool, attempt
                        return
                }
                resp, err = s.Do(rr.Request())
-               // if the error isn't temporary don't bother retrying
-               if err != nil && !IsTemporaryNetworkError(err) {
-                       return
-               }
                // we want to retry if err is not nil (e.g. transient network failure).  note that for failed authentication
                // resp and err will both have a value, so in this case we don't want to retry as it will never succeed.
                if err == nil && !ResponseHasStatusCode(resp, codes...) || IsTokenRefreshError(err) {

The debug output here is:

2019-11-28T14:50:12.538+0100 [DEBUG] plugin.terraform-provider-azurerm_v1.36.2: DDDDD ERR Get https://<storage_account_name>.queue.core.windows.net/?comp=properties&restype=service: dial tcp: lookup <storage_account_name>.queue.core.windows.net: no such host

This will never be a successful call for storage accounts that do not have a queue.

@alex-goncharov
Copy link
Contributor

@tombuildsstuff could you please assess this one, as it kills all plans with storage accounts that do not have queues.

@fox918
Copy link

fox918 commented Dec 2, 2019

I have the same issue.
On further examination, it terraform does not seem to hang when setting LRS as account_replication_type
(I have two identical deployment with this being the only perceived difference.)

@sunnynazar
Copy link

I am seeing terraform plan running for 8 mins on an average with 1.37.0 ... its really slow and gives a feeling that terraform plan is hung.

It seems its better to use 1.36.0 till 1.37.0 is stable in terms of performance.

@tombuildsstuff tombuildsstuff added this to the v1.39.0 milestone Dec 5, 2019
@r0bnet
Copy link
Contributor

r0bnet commented Dec 11, 2019

I have the same issue.
On further examination, it terraform does not seem to hang when setting LRS as account_replication_type
(I have two identical deployment with this being the only perceived difference.)

Hey @fox918,
this setting doesn't change anything in my case. I already set it to LRS but it's still slow as hell.
So it might not be related to that.

@sylus
Copy link

sylus commented Dec 11, 2019

Can confirm also have this same problem when updating the AzureRM provider. Exactly the same issue related to queue call.

@tombuildsstuff tombuildsstuff modified the milestones: v1.39.0, v1.40.0 Dec 12, 2019
@krispetkov
Copy link
Contributor

I have the same issue with the destroy of the storage account.
I have wait it for 16 hours before killing it and no results at the end.

@tombuildsstuff tombuildsstuff modified the milestones: v1.40.0, v1.41.0 Dec 19, 2019
@BadgerCode
Copy link

Happy New Year!

I am experiencing an issue which seems to be related:

  • Arbitrary, long delays when generating a plan (in either apply/plan)
  • Started happening around the same time (late November)
  • Same version of AzureRM (I have also tried 1.38.0 & 1.39.0)

However, my plan output hangs on seemingly random resources (depending on the workspace, and if any resources have been --target targetted).

I have seen the output freeze after azurerm_function_app, azurerm_app_service and custom module resources.

This happens on every single run.

When targetting one resource (with dependencies), the plan got stuck for 7:30 minutes.

2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: [DEBUG] AzureRM Response for https://management.azure.com/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-A/config/web?api-version=2018-02-01: 
2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: HTTP/2.0 200 OK
2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Cache-Control: no-cache
2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Content-Type: application/json
2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Date: Fri, 03 Jan 2020 11:11:31 GMT
2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Expires: -1
2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Pragma: no-cache
2020-01-03T11:11:31.231Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Server: Microsoft-IIS/10.0
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Strict-Transport-Security: max-age=31536000; includeSubDomains
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Vary: Accept-Encoding
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Aspnet-Version: 4.0.30319
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Content-Type-Options: nosniff
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Correlation-Request-Id: e9f9452f-61cc-6e9c-778b-cc1c475d94fb
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Ratelimit-Remaining-Subscription-Reads: 11988
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Request-Id: ea58e47b-868e-4ee7-8af7-f74513e566c9
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Routing-Request-Id: UKSOUTH2:20200103T111131Z:f7bafdbf-9c3a-4b3b-9e28-94c32cadec6b
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Powered-By: ASP.NET
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: 
2020-01-03T11:11:31.232Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: {"id":"/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-A/config/web","name":"REDACTED-WEBSITE-A","type":"Microsoft.Web/sites/config","location":"UK South","tags":{"product":"REDACTED"},"properties":{"numberOfWorkers":1,"defaultDocuments":["Default.htm","Default.html","Default.asp","index.htm","index.html","iisstart.htm","default.aspx","index.php"],"netFrameworkVersion":"v4.0","phpVersion":"5.6","pythonVersion":"","nodeVersion":"","linuxFxVersion":"","windowsFxVersion":null,"requestTracingEnabled":false,"remoteDebuggingEnabled":false,"remoteDebuggingVersion":null,"httpLoggingEnabled":false,"azureMonitorLogCategories":null,"logsDirectorySizeLimit":35,"detailedErrorLoggingEnabled":false,"publishingUsername":"$REDACTED-WEBSITE-A","publishingPassword":null,"appSettings":null,"metadata":null,"connectionStrings":null,"machineKey":null,"handlerMappings":null,"documentRoot":null,"scmType":"VSTSRM","use32BitWorkerProcess":true,"webSocketsEnabled":false,"alwaysOn":false,"javaVersion":null,"javaContainer":null,"javaContainerVersion":null,"appCommandLine":"","managedPipelineMode":"Integrated","virtualApplications":[{"virtualPath":"/","physicalPath":"site\\wwwroot","preloadEnabled":false,"virtualDirectories":null}],"winAuthAdminState":0,"winAuthTenantState":0,"customAppPoolIdentityAdminState":false,"customAppPoolIdentityTenantState":false,"runtimeADUser":null,"runtimeADUserPassword":null,"loadBalancing":"LeastRequests","routingRules":[],"experiments":{"rampUpRules":[]},"limits":null,"autoHealEnabled":false,"autoHealRules":null,"tracingOptions":null,"vnetName":"","siteAuthEnabled":false,"siteAuthSettings":{"enabled":null,"unauthenticatedClientAction":null,"tokenStoreEnabled":null,"allowedExternalRedirectUrls":null,"defaultProvider":null,"clientId":null,"clientSecret":null,"clientSecretCertificateThumbprint":null,"issuer":null,"allowedAudiences":null,"additionalLoginParams":null,"isAadAutoProvisioned":false,"googleClientId":null,"googleClientSecret":null,"googleOAuthScopes":null,"facebookAppId":null,"facebookAppSecret":null,"facebookOAuthScopes":null,"twitterConsumerKey":null,"twitterConsumerSecret":null,"microsoftAccountClientId":null,"microsoftAccountClientSecret":null,"microsoftAccountOAuthScopes":null},"cors":{"allowedOrigins":["https://functions-staging.azure.com","https://functions.azure.com","https://functions-next.azure.com"],"supportCredentials":false},"push":null,"apiDefinition":null,"apiManagementConfig":null,"autoSwapSlotName":null,"localMySqlEnabled":false,"managedServiceIdentityId":null,"xManagedServiceIdentityId":null,"ipSecurityRestrictions":null,"scmIpSecurityRestrictions":null,"scmIpSecurityRestrictionsUseMain":false,"http20Enabled":false,"minTlsVersion":"1.2","ftpsState":"AllAllowed","reservedInstanceCount":0,"preWarmedInstanceCount":null,"healthCheckPath":null,"fileChangeAuditEnabled":false,"functionsRuntimeScaleMonitoringEnabled":false,"websiteTimeZone":null}}
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: [DEBUG] AzureRM Response for https://management.azure.com/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-B/config/web?api-version=2018-02-01: 
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: HTTP/2.0 200 OK
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Cache-Control: no-cache
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Content-Type: application/json
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Date: Fri, 03 Jan 2020 11:11:31 GMT
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Expires: -1
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Pragma: no-cache
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Server: Microsoft-IIS/10.0
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Strict-Transport-Security: max-age=31536000; includeSubDomains
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Vary: Accept-Encoding
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Aspnet-Version: 4.0.30319
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Content-Type-Options: nosniff
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Correlation-Request-Id: e9f9452f-61cc-6e9c-778b-cc1c475d94fb
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Ratelimit-Remaining-Subscription-Reads: 11988
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Request-Id: 66706098-c95d-4528-a400-15df7c741c5c
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Routing-Request-Id: UKSOUTH2:20200103T111131Z:d69501f5-68a2-4a11-a5bb-a7c8d60f4ccf
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Powered-By: ASP.NET
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: 
2020-01-03T11:11:31.301Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: {"id":"/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-B/config/web","name":"REDACTED-WEBSITE-B","type":"Microsoft.Web/sites/config","location":"UK South","tags":{"product":"REDACTED"},"properties":{"numberOfWorkers":1,"defaultDocuments":["Default.htm","Default.html","Default.asp","index.htm","index.html","iisstart.htm","default.aspx","index.php"],"netFrameworkVersion":"v4.0","phpVersion":"5.6","pythonVersion":"","nodeVersion":"","linuxFxVersion":"","windowsFxVersion":null,"requestTracingEnabled":false,"remoteDebuggingEnabled":false,"remoteDebuggingVersion":null,"httpLoggingEnabled":false,"azureMonitorLogCategories":null,"logsDirectorySizeLimit":35,"detailedErrorLoggingEnabled":false,"publishingUsername":"$REDACTED-WEBSITE-B","publishingPassword":null,"appSettings":null,"metadata":null,"connectionStrings":null,"machineKey":null,"handlerMappings":null,"documentRoot":null,"scmType":"VSTSRM","use32BitWorkerProcess":true,"webSocketsEnabled":false,"alwaysOn":false,"javaVersion":null,"javaContainer":null,"javaContainerVersion":null,"appCommandLine":"","managedPipelineMode":"Integrated","virtualApplications":[{"virtualPath":"/","physicalPath":"site\\wwwroot","preloadEnabled":false,"virtualDirectories":null}],"winAuthAdminState":0,"winAuthTenantState":0,"customAppPoolIdentityAdminState":false,"customAppPoolIdentityTenantState":false,"runtimeADUser":null,"runtimeADUserPassword":null,"loadBalancing":"LeastRequests","routingRules":[],"experiments":{"rampUpRules":[]},"limits":null,"autoHealEnabled":false,"autoHealRules":null,"tracingOptions":null,"vnetName":"","siteAuthEnabled":false,"siteAuthSettings":{"enabled":null,"unauthenticatedClientAction":null,"tokenStoreEnabled":null,"allowedExternalRedirectUrls":null,"defaultProvider":null,"clientId":null,"clientSecret":null,"clientSecretCertificateThumbprint":null,"issuer":null,"allowedAudiences":null,"additionalLoginParams":null,"isAadAutoProvisioned":false,"googleClientId":null,"googleClientSecret":null,"googleOAuthScopes":null,"facebookAppId":null,"facebookAppSecret":null,"facebookOAuthScopes":null,"twitterConsumerKey":null,"twitterConsumerSecret":null,"microsoftAccountClientId":null,"microsoftAccountClientSecret":null,"microsoftAccountOAuthScopes":null},"cors":{"allowedOrigins":["https://functions-staging.azure.com","https://functions.azure.com","https://functions-next.azure.com"],"supportCredentials":false},"push":null,"apiDefinition":null,"apiManagementConfig":null,"autoSwapSlotName":null,"localMySqlEnabled":false,"managedServiceIdentityId":null,"xManagedServiceIdentityId":null,"ipSecurityRestrictions":null,"scmIpSecurityRestrictions":null,"scmIpSecurityRestrictionsUseMain":false,"http20Enabled":false,"minTlsVersion":"1.2","ftpsState":"AllAllowed","reservedInstanceCount":0,"preWarmedInstanceCount":null,"healthCheckPath":null,"fileChangeAuditEnabled":false,"functionsRuntimeScaleMonitoringEnabled":false,"websiteTimeZone":null}}
2020/01/03 11:18:57 [DEBUG] ReferenceTransformer: "module.REDACTED.module.REDACTED.azurerm_function_app.REDACTED-WEBSITE-C" references: []
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: [DEBUG] AzureRM Request: 
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: GET /subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-C?api-version=2018-02-01 HTTP/1.1
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Host: management.azure.com
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: User-Agent: Go/go1.12.6 (amd64-windows) go-autorest/v13.3.0 Azure-SDK-For-Go/v36.2.0 web/2018-02-01 HashiCorp Terraform/0.12.17 (+https://www.terraform.io) Terraform Plugin SDK/1.1.1 terraform-provider-azurerm/1.39.0 pid-222c6c49-1b0a-5959-a213-6608f9eb8820
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Correlation-Request-Id: e9f9452f-61cc-6e9c-778b-cc1c475d94fb
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Accept-Encoding: gzip
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: 
2020-01-03T11:18:57.619Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: 
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: [DEBUG] AzureRM Response for https://management.azure.com/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-C?api-version=2018-02-01: 
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: HTTP/2.0 200 OK
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Cache-Control: no-cache
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Content-Type: application/json
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Date: Fri, 03 Jan 2020 11:18:57 GMT
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Etag: "1D5C158DBBD5980"
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Expires: -1
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Pragma: no-cache
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Server: Microsoft-IIS/10.0
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Strict-Transport-Security: max-age=31536000; includeSubDomains
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Vary: Accept-Encoding
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Aspnet-Version: 4.0.30319
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Content-Type-Options: nosniff
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Correlation-Request-Id: e9f9452f-61cc-6e9c-778b-cc1c475d94fb
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Ratelimit-Remaining-Subscription-Reads: 11997
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Request-Id: 8c5effb9-899e-47a6-b77e-c613ed483e81
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Routing-Request-Id: UKSOUTH2:20200103T111857Z:06d9f84f-f97f-444b-a242-47562a2fe5e3
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Powered-By: ASP.NET
2020-01-03T11:18:57.873Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: 
2020-01-03T11:18:57.874Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: {"id":"/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-C","name":"REDACTED-WEBSITE-C","type":"Microsoft.Web/sites","kind":"functionapp","location":"UK South","tags":{"env":"prod","product":"REDACTED","qos":"a"},"properties":{"name":"REDACTED-WEBSITE-C","state":"Running","hostNames":["REDACTED-WEBSITE-C.azurewebsites.net"],"webSpace":"REDACTED-UKSouthwebspace","selfLink":"https://waws-prod-ln1-013.api.azurewebsites.windows.net:454/subscriptions/REDACTED/webspaces/REDACTED-UKSouthwebspace/sites/REDACTED-WEBSITE-C","repositorySiteName":"REDACTED-WEBSITE-C","owner":null,"usageState":"Normal","enabled":true,"adminEnabled":true,"enabledHostNames":["REDACTED-WEBSITE-C.azurewebsites.net","REDACTED-WEBSITE-C.scm.azurewebsites.net"],"siteProperties":{"metadata":null,"properties":[{"name":"LinuxFxVersion","value":""},{"name":"WindowsFxVersion","value":null}],"appSettings":null},"availabilityState":"Normal","sslCertificates":null,"csrs":[],"cers":null,"siteMode":null,"hostNameSslStates":[{"name":"REDACTED-WEBSITE-C.azurewebsites.net","sslState":"Disabled","ipBasedSslResult":null,"virtualIP":null,"thumbprint":null,"toUpdate":null,"toUpdateIpBasedSsl":null,"ipBasedSslState":"NotConfigured","hostType":"Standard"},{"name":"REDACTED-WEBSITE-C.scm.azurewebsites.net","sslState":"Disabled","ipBasedSslResult":null,"virtualIP":null,"thumbprint":null,"toUpdate":null,"toUpdateIpBasedSsl":null,"ipBasedSslState":"NotConfigured","hostType":"Repository"}],"computeMode":null,"serverFarm":null,"serverFarmId":"/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/serverfarms/REDACTED","reserved":false,"isXenon":false,"hyperV":false,"lastModifiedTimeUtc":"2020-01-02T10:39:06.52","storageRecoveryDefaultState":"Running","contentAvailabilityState":"Normal","runtimeAvailabilityState":"Normal","siteConfig":null,"deploymentId":"REDACTED-WEBSITE-C","trafficManagerHostNames":null,"sku":"Dynamic","scmSiteAlsoStopped":false,"targetSwapSlot":null,"hostingEnvironment":null,"hostingEnvironmentProfile":null,"clientAffinityEnabled":false,"clientCertEnabled":false,"clientCertExclusionPaths":null,"hostNamesDisabled":false,"domainVerificationIdentifiers":null,"customDomainVerificationId":"E1BEA734373D07AB8390573B757E2B31D5F631BD41D46F01E24D64D22263954D","kind":"functionapp","inboundIpAddress":"51.140.59.233","possibleInboundIpAddresses":"51.140.59.233","outboundIpAddresses":"51.140.59.233,51.140.68.158,51.140.70.218,51.140.120.15,51.140.60.60","possibleOutboundIpAddresses":"51.140.59.233,51.140.68.158,51.140.70.218,51.140.120.15,51.140.60.60,51.140.73.7,51.140.60.160","containerSize":1536,"dailyMemoryTimeQuota":0,"suspendedTill":null,"siteDisabledReason":0,"functionExecutionUnitsCache":null,"maxNumberOfWorkers":null,"homeStamp":"waws-prod-ln1-013","cloningInfo":null,"hostingEnvironmentId":null,"tags":{"env":"prod","product":"REDACTED","qos":"a"},"resourceGroup":"REDACTED","defaultHostName":"REDACTED-WEBSITE-C.azurewebsites.net","slotSwapStatus":null,"httpsOnly":false,"redundancyMode":"None","inProgressOperationId":null,"geoDistributions":null,"privateEndpointConnections":[],"buildVersion":null,"targetBuildVersion":null}}
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: [DEBUG] AzureRM Request: 
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: POST /subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-C/config/appsettings/list?api-version=2018-02-01 HTTP/1.1
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Host: management.azure.com
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: User-Agent: Go/go1.12.6 (amd64-windows) go-autorest/v13.3.0 Azure-SDK-For-Go/v36.2.0 web/2018-02-01 HashiCorp Terraform/0.12.17 (+https://www.terraform.io) Terraform Plugin SDK/1.1.1 terraform-provider-azurerm/1.39.0 pid-222c6c49-1b0a-5959-a213-6608f9eb8820
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Content-Length: 0
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: X-Ms-Correlation-Request-Id: e9f9452f-61cc-6e9c-778b-cc1c475d94fb
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: Accept-Encoding: gzip
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: 
2020-01-03T11:18:57.875Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: 
2020-01-03T11:18:58.043Z [DEBUG] plugin.terraform-provider-azurerm_v1.39.0_x4.exe: [DEBUG] AzureRM Response for https://management.azure.com/subscriptions/REDACTED/resourceGroups/REDACTED/providers/Microsoft.Web/sites/REDACTED-WEBSITE-C/config/appsettings/list?api-version=2018-02-01: 

@embik
Copy link

embik commented Jan 8, 2020

If I understand this issue correctly, it's supposed to be resolved by #5316. Just as a note for everyone looking into this.

@tombuildsstuff
Copy link
Contributor

tombuildsstuff commented Jan 14, 2020

👋

From what I can tell this should be fixed in #5316 - since that's been merged I'm going to close this issue for the moment; but if you're still seeing this after upgrading to v1.41 (once that's released) please let us know and we'll take another look :)

Thanks!

@krispetkov
Copy link
Contributor

@tombuildsstuff do you mean v1.41 (instead v1.40)?

@tombuildsstuff
Copy link
Contributor

@krispetkov yes 🤦‍♂ - thanks for pointing that out, will update now :)

@ghost
Copy link

ghost commented Jan 16, 2020

This has been released in version 1.41.0 of the provider. Please see the Terraform documentation on provider versioning or reach out if you need any assistance upgrading. As an example:

provider "azurerm" {
    version = "~> 1.41.0"
}
# ... other configuration ...

@BadgerCode
Copy link

Thank you!
This has fixed the problem.

@krispetkov
Copy link
Contributor

krispetkov commented Jan 20, 2020

I'm still facing the same issue. Unfortunately the last update of the provider didn't fix the issue for me.
@tombuildsstuff can you please check this issue #5434 ?
I just want to know if I'm doing something wrong or the issue is still present for some reason.

@marty2bell
Copy link

marty2bell commented Jan 20, 2020

I seem to be having this issue (terraform just hangs when refreshing it's state) with the 1.41 version of the azurerm provider using terraform version 0.12.19

Any ideas, as I'm pretty much blocked applying updates to our clusters?

I'm using remote state (azure storage account) and I can see terraform acquiring a state lock, refreshing all the resources and then it just hangs there......

@alex-goncharov
Copy link
Contributor

alex-goncharov commented Jan 20, 2020

@krispetkov @marty2bell is it storage account resource that delays the plan, or something else? Running terraform with TF_LOG=TRACE could give you a clue.

1.41.0 had resolved the issue for us.

@krispetkov
Copy link
Contributor

@alex-goncharov running the destroy with TF_LOG=TRACE I'm gettings recurring logs like this one:

2020/01/17 12:05:07 [TRACE] dag/walk: vertex "output.my_storage_primary_file_endpoint (destroy)", waiting for: "output.my_storage_account_secondary_key (destroy)"
2020/01/17 12:05:07 [TRACE] dag/walk: vertex "output.my_storage_account_primary_key (destroy)", waiting for: "output.my_storage_account (destroy)"
2020/01/17 12:05:07 [TRACE] dag/walk: vertex "root", waiting for: "meta.count-boundary (count boundary fixup)"
2020/01/17 12:05:07 [TRACE] dag/walk: vertex "provider.azurerm (close)", waiting for: "azurerm_storage_account.my_storage_azure (destroy)"

@alex-goncharov
Copy link
Contributor

that looks normal, destroying azure storage account is never quick

The issue in question would appear during the plan.

@krispetkov
Copy link
Contributor

krispetkov commented Jan 23, 2020

@alex-goncharov I have found the problem and the reason. Tou can see it described here but for now I don't have a solution...

Do you use network rules for your storage account by any chance?

@ghost
Copy link

ghost commented Mar 28, 2020

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.

If you feel this issue should be reopened, we encourage creating a new issue linking back to this one for added context. If you feel I made an error 🤖 🙉 , please reach out to my human friends 👉 [email protected]. Thanks!

@ghost ghost locked and limited conversation to collaborators Mar 28, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests