search

fortinetdev / terraform-provider-fortimanager

Mozilla Public License 2.0
11 stars 10 forks source link

Terraform apply hangs indefinitely when creating more than 24 policies #15

Closed KB30497 closed 2 years ago

KB30497 commented 2 years ago

Issue

We're seeing a consistent issue while creating more than 24 policies in the same Terraform apply. Once the amount of policies being created is >=25, the apply will hang after creating the 24th policy and keep trying to create the rest of the policies indefinitely.

Sometimes the rules after #24 get created and sometimes they don't. It seems that the Fortimanager API stops responding and Terraform gets stuck waiting for a response, so even if the rules are created they don't get entered into Terraform state.

Terraform Version

Terraform v1.1.4 on windows_amd64 provider registry.terraform.io/fortinetdev/fortimanager v1.3.6

Fortimanager Version

FMG-VM64-GCP Firmware Version | v6.4.7-build2412 210902 (GA)

Affected Resource(s)

fortimanager_packages_firewall_policy fortimanager_packages_firewall_localinpolicy

Terraform Configuration Files

resource "fortimanager_packages_firewall_policy" "test_policies" {
  count                   = 25
  action                  = "accept"
  dstaddr                 = ["all"]
  dstintf                 = ["any"]
  logtraffic              = "all"
  name                    = "policy-${count.index+1}"
  pkg                     = "terraform-fortigate-01"
  policyid                = count.index+1
  schedule                = "always"
  service                 = ["ALL"]
  srcaddr                 = ["all"]
  srcintf                 = ["any"]
  status                  = "enable"
}

Apply Output (Abbreviated)

Terraform used the selected providers to generate the following execution
plan. Resource actions are indicated with the following symbols:
  + create

Plan: 25 to add, 0 to change, 0 to destroy.
fortimanager_packages_firewall_policy.test_policies[0]: Creation complete after 1s [id=1]
fortimanager_packages_firewall_policy.test_policies[5]: Creation complete after 1s [id=6]
fortimanager_packages_firewall_policy.test_policies[20]: Creation complete after 1s [id=21]
fortimanager_packages_firewall_policy.test_policies[12]: Creation complete after 2s [id=13]
fortimanager_packages_firewall_policy.test_policies[23]: Creation complete after 2s [id=24]
fortimanager_packages_firewall_policy.test_policies[21]: Creation complete after 2s [id=22]
fortimanager_packages_firewall_policy.test_policies[7]: Creation complete after 2s [id=8]
fortimanager_packages_firewall_policy.test_policies[13]: Creation complete after 3s [id=14]
fortimanager_packages_firewall_policy.test_policies[3]: Creation complete after 3s [id=4]
fortimanager_packages_firewall_policy.test_policies[18]: Creation complete after 3s [id=19]
fortimanager_packages_firewall_policy.test_policies[10]: Creation complete after 2s [id=11]
fortimanager_packages_firewall_policy.test_policies[15]: Creation complete after 4s [id=16]
fortimanager_packages_firewall_policy.test_policies[6]: Creation complete after 4s [id=7]
fortimanager_packages_firewall_policy.test_policies[22]: Creation complete after 4s [id=23]
fortimanager_packages_firewall_policy.test_policies[2]: Creation complete after 4s [id=3]
fortimanager_packages_firewall_policy.test_policies[24]: Creation complete after 5s [id=25]
fortimanager_packages_firewall_policy.test_policies[9]: Creation complete after 5s [id=10]
fortimanager_packages_firewall_policy.test_policies[1]: Creation complete after 4s [id=2]
fortimanager_packages_firewall_policy.test_policies[8]: Creation complete after 1s [id=9]
fortimanager_packages_firewall_policy.test_policies[17]: Creation complete after 1s [id=18]
fortimanager_packages_firewall_policy.test_policies[16]: Creation complete after 4s [id=17]
fortimanager_packages_firewall_policy.test_policies[11]: Creation complete after 5s [id=12]
fortimanager_packages_firewall_policy.test_policies[14]: Creation complete after 2s [id=15]
fortimanager_packages_firewall_policy.test_policies[4]: Creation complete after 4s [id=5]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [10s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [20s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [30s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [40s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [50s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [1m0s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [1m10s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [1m20s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [1m30s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [1m40s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [1m50s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [2m0s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [2m10s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [2m20s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [2m30s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [2m40s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [2m50s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [3m0s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [3m10s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [3m20s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [3m30s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [3m40s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [3m50s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [4m0s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [4m10s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [4m20s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [4m30s elapsed]
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [4m40s elapsed]

Debug Output (Abbreviated)

2022-03-23T18:14:39.967-0400 [TRACE] readDiff: Read Create change from plan for fortimanager_packages_firewall_policy.test_policies[19]
2022-03-23T18:14:39.967-0400 [TRACE] readResourceInstanceState: reading state for fortimanager_packages_firewall_policy.test_policies[19]
2022-03-23T18:14:39.967-0400 [TRACE] readResourceInstanceState: no state present for fortimanager_packages_firewall_policy.test_policies[19]
2022-03-23T18:14:39.968-0400 [TRACE] readDiff: Read Create change from plan for fortimanager_packages_firewall_policy.test_policies[19]
2022-03-23T18:14:39.968-0400 [TRACE] Re-validating config for "fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:14:39.969-0400 [TRACE] GRPCProvider: ValidateResourceConfig
2022-03-23T18:14:39.970-0400 [TRACE] GRPCProvider: PlanResourceChange
2022-03-23T18:14:39.977-0400 [WARN]  Provider "registry.terraform.io/fortinetdev/fortimanager" produced an invalid plan for fortimanager_packages_firewall_policy.test_policies[19], but we are 
tolerating it because it is using the legacy plugin SDK.
    The following problems may be the cause of any confusing errors from downstream operations:
      - .scopetype: planned value cty.StringVal("inherit") for a non-computed attribute
      - .dynamic_sort_subtable: planned value cty.StringVal("false") for a non-computed attribute
2022-03-23T18:14:39.977-0400 [TRACE] checkPlannedChange: Verifying that actual change (action Create) matches planned change (action Create)
2022-03-23T18:14:39.978-0400 [TRACE] readResourceInstanceState: reading state for fortimanager_packages_firewall_policy.test_policies[19]
2022-03-23T18:14:39.978-0400 [TRACE] readResourceInstanceState: no state present for fortimanager_packages_firewall_policy.test_policies[19]
fortimanager_packages_firewall_policy.test_policies[19]: Creating...
2022-03-23T18:14:39.978-0400 [INFO]  Starting apply for fortimanager_packages_firewall_policy.test_policies[19]
2022-03-23T18:14:39.978-0400 [DEBUG] fortimanager_packages_firewall_policy.test_policies[19]: applying the planned Create change
2022-03-23T18:14:39.978-0400 [TRACE] GRPCProvider: ApplyResourceChange
2022-03-23T18:14:46.716-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:14:47.864-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [10s elapsed]
2022-03-23T18:14:51.718-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:14:52.865-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
2022-03-23T18:14:56.719-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:14:57.865-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [20s elapsed]
2022-03-23T18:15:01.719-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:15:02.867-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
2022-03-23T18:15:06.721-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:15:07.867-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [30s elapsed]
2022-03-23T18:15:11.723-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:15:12.869-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
2022-03-23T18:15:16.723-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:15:17.870-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [40s elapsed]
2022-03-23T18:15:21.723-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:15:22.871-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
2022-03-23T18:15:26.728-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:15:27.873-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
fortimanager_packages_firewall_policy.test_policies[19]: Still creating... [50s elapsed]
2022-03-23T18:15:31.729-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
2022-03-23T18:15:32.874-0400 [TRACE] dag/walk: vertex "root" is waiting for "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)"
2022-03-23T18:15:36.731-0400 [TRACE] dag/walk: vertex "provider[\"registry.terraform.io/fortinetdev/fortimanager\"] (close)" is waiting for 
"fortimanager_packages_firewall_policy.test_policies[19]"
KB30497 commented 2 years ago

From debugs on the Fortimanager side, the issue is possibly Terraform creating a policy and then failing to send a GET for the policy to retrieve its config and put it into state.

For example when "policy-21" is the policy that Terraform gets hung up on, the policy gets created:

Request:
{ "client": "\/usr\/local\/apache2\/bin\/httpd:18522", "method": "add", "params": [{ "data": { "action": "accept", "dstaddr": ["all"], "dstintf": ["any"], "logtraffic": "all", "name": "policy-21", "policyid": 21, "schedule": "always", "service": ["ALL"], "srcaddr": ["all"], "srcintf": ["any"], "status": "enable"}, "url": "\/pm\/config\/adom\/<adom>\/pkg\/<package>\/firewall\/policy"}], "session": "...", "src": "...", "verbose": 1}

But there's no corresponding GET coming from Terraform.

Compared to a policy that was created and put into state correctly ("policy-9"):

Request:
{ "client": "\/usr\/local\/apache2\/bin\/httpd:17716", "method": "add", "params": [{ "data": { "action": "accept", "dstaddr": ["all"], "dstintf": ["any"], "logtraffic": "all", "name": "policy-9", "policyid": 9, "schedule": "always", "service": ["ALL"], "srcaddr": ["all"], "srcintf": ["any"], "status": "enable"}, "url": "\/pm\/config\/adom\/<adom>\/pkg\/<package>\/firewall\/policy"}], "session": "...", "src": "...", "verbose": 1}

Request:
{ "client": "\/usr\/local\/apache2\/bin\/httpd:17716", "method": "get", "params": [{ "data": null, "url": "\/pm\/config\/adom\/<adom>\/pkg\/<package>\/firewall\/policy\/9"}], "session": "...", "src": "...", "verbose": 1}

I don't know what the significance of 25 policies is but that seems to consistently be the number where this starts happening.

lix-fortinet commented 2 years ago

Hi @KB30497,

Thank you for raising this issue. Team are working on it now. We will get back to you once it's resolved.

Thanks, Xing

lix-fortinet commented 2 years ago

Hi @KB30497,

This issue has been fixed in the latest release of FortiManager Terraform provider v1.4.0. Please use the latest version of FortiManager Terraform provider and try it again.

Please let me know if you have any questions.

Thanks, Xing

KB30497 commented 2 years ago

Confirmed that I'm no longer seeing this behavior - I created a few hundred policies at once with no issues.

Thank you.