search

crossplane / terrajet

Generate Crossplane Providers from any Terraform Provider
https://crossplane.io
Apache License 2.0
290 stars 38 forks source link

Unnecessary reconcile after deletion #109

Closed muvaf closed 2 years ago

muvaf commented 2 years ago

What happened?

In debug logs, I see that for some reason the finalizer removal call doesn't succeed due to infamous custom resource version is old error and we get re-queued. Since we remove the directory before the finalizer call, in the next reconciliation we need to init the directory again to see whether resource exists and only after that we confirm the deletion. This causes the deletion to take longer than it needs to.

How can we reproduce it?

Use any sync examples like AWS VPC with debug logging enabled.

ulucinar commented 2 years ago

Some logs collected while trying to reproduce this issue:

2022-03-08T09:52:35.563+0300    DEBUG   provider-jet-aws        Reconciling     {"controller": "managed/ec2.aws.jet.crossplane.io/v1alpha2, kind=vpc", "request": "/sample-vpc"}
2022-03-08T09:52:47.485+0300    DEBUG   provider-jet-aws        refresh ended   {"workspace": "/var/folders/ws/3fn5p0_d45v6vx_z1_sxjxm80000gn/T/76377904-3bef-471c-8f07-dc00589a6d3b", "out": "{\"@level\":\"info\",\"@message\":\"Terraform 1.0.3\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:35.811138+03:00\",\"terraform\":\"1.0.3\",\"type\":\"version\",\"ui\":\"0.1.0\"}\n{\"@level\":\"info\",\"@message\":\"aws_vpc.sample-vpc: Refreshing state... [id=vpc-067f4b9d7da65fba2]\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:39.046598+03:00\",\"hook\":{\"resource\":{\"addr\":\"aws_vpc.sample-vpc\",\"module\":\"\",\"resource\":\"aws_vpc.sample-vpc\",\"implied_provider\":\"aws\",\"resource_type\":\"aws_vpc\",\"resource_name\":\"sample-vpc\",\"resource_key\":null},\"id_key\":\"id\",\"id_value\":\"vpc-067f4b9d7da65fba2\"},\"type\":\"refresh_start\"}\n{\"@level\":\"info\",\"@message\":\"aws_vpc.sample-vpc: Refresh complete [id=vpc-067f4b9d7da65fba2]\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:47.448111+03:00\",\"hook\":{\"resource\":{\"addr\":\"aws_vpc.sample-vpc\",\"module\":\"\",\"resource\":\"aws_vpc.sample-vpc\",\"implied_provider\":\"aws\",\"resource_type\":\"aws_vpc\",\"resource_name\":\"sample-vpc\",\"resource_key\":null},\"id_key\":\"id\",\"id_value\":\"vpc-067f4b9d7da65fba2\"},\"type\":\"refresh_complete\"}\n{\"@level\":\"info\",\"@message\":\"Plan: 0 to add, 0 to change, 0 to destroy.\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:47.458065+03:00\",\"changes\":{\"add\":0,\"change\":0,\"remove\":0,\"operation\":\"plan\"},\"type\":\"change_summary\"}\n{\"@level\":\"info\",\"@message\":\"Apply complete! Resources: 0 added, 0 changed, 0 destroyed.\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:47.480734+03:00\",\"changes\":{\"add\":0,\"change\":0,\"remove\":0,\"operation\":\"apply\"},\"type\":\"change_summary\"}\n{\"@level\":\"info\",\"@message\":\"Outputs: 0\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:47.480754+03:00\",\"outputs\":{},\"type\":\"outputs\"}\n"}
2022-03-08T09:52:50.722+0300    DEBUG   provider-jet-aws        plan ended      {"workspace": "/var/folders/ws/3fn5p0_d45v6vx_z1_sxjxm80000gn/T/76377904-3bef-471c-8f07-dc00589a6d3b", "out": "{\"@level\":\"info\",\"@message\":\"Terraform 1.0.3\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:47.514294+03:00\",\"terraform\":\"1.0.3\",\"type\":\"version\",\"ui\":\"0.1.0\"}\n{\"@level\":\"info\",\"@message\":\"Plan: 0 to add, 0 to change, 0 to destroy.\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:50.715283+03:00\",\"changes\":{\"add\":0,\"change\":0,\"remove\":0,\"operation\":\"plan\"},\"type\":\"change_summary\"}\n"}
2022-03-08T09:53:06.015+0300    DEBUG   provider-jet-aws        destroy ended   {"workspace": "/var/folders/ws/3fn5p0_d45v6vx_z1_sxjxm80000gn/T/76377904-3bef-471c-8f07-dc00589a6d3b", "out": "{\"@level\":\"info\",\"@message\":\"Terraform 1.0.3\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:50.755297+03:00\",\"terraform\":\"1.0.3\",\"type\":\"version\",\"ui\":\"0.1.0\"}\n{\"@level\":\"info\",\"@message\":\"aws_vpc.sample-vpc: Refreshing state... [id=vpc-067f4b9d7da65fba2]\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:52:53.756081+03:00\",\"hook\":{\"resource\":{\"addr\":\"aws_vpc.sample-vpc\",\"module\":\"\",\"resource\":\"aws_vpc.sample-vpc\",\"implied_provider\":\"aws\",\"resource_type\":\"aws_vpc\",\"resource_name\":\"sample-vpc\",\"resource_key\":null},\"id_key\":\"id\",\"id_value\":\"vpc-067f4b9d7da65fba2\"},\"type\":\"refresh_start\"}\n{\"@level\":\"info\",\"@message\":\"aws_vpc.sample-vpc: Refresh complete [id=vpc-067f4b9d7da65fba2]\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:02.137707+03:00\",\"hook\":{\"resource\":{\"addr\":\"aws_vpc.sample-vpc\",\"module\":\"\",\"resource\":\"aws_vpc.sample-vpc\",\"implied_provider\":\"aws\",\"resource_type\":\"aws_vpc\",\"resource_name\":\"sample-vpc\",\"resource_key\":null},\"id_key\":\"id\",\"id_value\":\"vpc-067f4b9d7da65fba2\"},\"type\":\"refresh_complete\"}\n{\"@level\":\"info\",\"@message\":\"aws_vpc.sample-vpc: Plan to delete\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:02.348060+03:00\",\"change\":{\"resource\":{\"addr\":\"aws_vpc.sample-vpc\",\"module\":\"\",\"resource\":\"aws_vpc.sample-vpc\",\"implied_provider\":\"aws\",\"resource_type\":\"aws_vpc\",\"resource_name\":\"sample-vpc\",\"resource_key\":null},\"action\":\"delete\"},\"type\":\"planned_change\"}\n{\"@level\":\"info\",\"@message\":\"Plan: 0 to add, 0 to change, 1 to destroy.\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:02.348123+03:00\",\"changes\":{\"add\":0,\"change\":0,\"remove\":1,\"operation\":\"plan\"},\"type\":\"change_summary\"}\n{\"@level\":\"info\",\"@message\":\"aws_vpc.sample-vpc: Destroying... [id=vpc-067f4b9d7da65fba2]\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:04.738175+03:00\",\"hook\":{\"resource\":{\"addr\":\"aws_vpc.sample-vpc\",\"module\":\"\",\"resource\":\"aws_vpc.sample-vpc\",\"implied_provider\":\"aws\",\"resource_type\":\"aws_vpc\",\"resource_name\":\"sample-vpc\",\"resource_key\":null},\"action\":\"delete\",\"id_key\":\"id\",\"id_value\":\"vpc-067f4b9d7da65fba2\"},\"type\":\"apply_start\"}\n{\"@level\":\"info\",\"@message\":\"aws_vpc.sample-vpc: Destruction complete after 1s\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:05.954188+03:00\",\"hook\":{\"resource\":{\"addr\":\"aws_vpc.sample-vpc\",\"module\":\"\",\"resource\":\"aws_vpc.sample-vpc\",\"implied_provider\":\"aws\",\"resource_type\":\"aws_vpc\",\"resource_name\":\"sample-vpc\",\"resource_key\":null},\"action\":\"delete\",\"elapsed_seconds\":1},\"type\":\"apply_complete\"}\n{\"@level\":\"info\",\"@message\":\"Destroy complete! Resources: 1 destroyed.\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:06.004144+03:00\",\"changes\":{\"add\":0,\"change\":0,\"remove\":1,\"operation\":\"destroy\"},\"type\":\"change_summary\"}\n"}
2022-03-08T09:53:06.016+0300    DEBUG   provider-jet-aws        Successfully requested deletion of external resource    {"controller": "managed/ec2.aws.jet.crossplane.io/v1alpha2, kind=vpc", "request": "/sample-vpc", "uid": "76377904-3bef-471c-8f07-dc00589a6d3b", "version": "1009043", "external-name": "vpc-067f4b9d7da65fba2", "deletion-timestamp": "2022-03-08 09:52:35 +0300 +03"}
2022-03-08T09:53:06.016+0300    DEBUG   controller-runtime.manager.events       Normal  {"object": {"kind":"VPC","name":"sample-vpc","uid":"76377904-3bef-471c-8f07-dc00589a6d3b","apiVersion":"ec2.aws.jet.crossplane.io/v1alpha2","resourceVersion":"1009043"}, "reason": "DeletedExternalResource", "message": "Successfully requested deletion of external resource"}
2022-03-08T09:53:06.042+0300    DEBUG   provider-jet-aws        Reconciling     {"controller": "managed/ec2.aws.jet.crossplane.io/v1alpha2, kind=vpc", "request": "/sample-vpc"}
2022-03-08T09:53:09.313+0300    DEBUG   provider-jet-aws        refresh ended   {"workspace": "/var/folders/ws/3fn5p0_d45v6vx_z1_sxjxm80000gn/T/76377904-3bef-471c-8f07-dc00589a6d3b", "out": "{\"@level\":\"info\",\"@message\":\"Terraform 1.0.3\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:06.093774+03:00\",\"terraform\":\"1.0.3\",\"type\":\"version\",\"ui\":\"0.1.0\"}\n{\"@level\":\"info\",\"@message\":\"Plan: 0 to add, 0 to change, 0 to destroy.\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:09.281036+03:00\",\"changes\":{\"add\":0,\"change\":0,\"remove\":0,\"operation\":\"plan\"},\"type\":\"change_summary\"}\n{\"@level\":\"info\",\"@message\":\"Apply complete! Resources: 0 added, 0 changed, 0 destroyed.\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:09.303318+03:00\",\"changes\":{\"add\":0,\"change\":0,\"remove\":0,\"operation\":\"apply\"},\"type\":\"change_summary\"}\n{\"@level\":\"info\",\"@message\":\"Outputs: 0\",\"@module\":\"terraform.ui\",\"@timestamp\":\"2022-03-08T09:53:09.303385+03:00\",\"outputs\":{},\"type\":\"outputs\"}\n"}
2022-03-08T09:53:09.338+0300    DEBUG   provider-jet-aws        Successfully deleted managed resource   {"controller": "managed/ec2.aws.jet.crossplane.io/v1alpha2, kind=vpc", "request": "/sample-vpc", "uid": "76377904-3bef-471c-8f07-dc00589a6d3b", "version": "1009112", "external-name": "vpc-067f4b9d7da65fba2", "deletion-timestamp": "2022-03-08 09:52:35 +0300 +03"}
2022-03-08T09:53:09.339+0300    DEBUG   provider-jet-aws        Reconciling     {"controller": "managed/ec2.aws.jet.crossplane.io/v1alpha2, kind=vpc", "request": "/sample-vpc"}
2022-03-08T09:53:09.339+0300    DEBUG   provider-jet-aws        Cannot get managed resource     {"controller": "managed/ec2.aws.jet.crossplane.io/v1alpha2, kind=vpc", "request": "/sample-vpc", "error": "VPC.ec2.aws.jet.crossplane.io \"sample-vpc\" not found"}
2022-03-08T09:53:09.438+0300    DEBUG   provider-jet-aws        Reconciling     {"controller": "providerconfig/providerconfig.aws.jet.crossplane.io", "request": "/default"}
2022-03-08T09:53:09.459+0300    DEBUG   provider-jet-aws        Reconciling     {"controller": "providerconfig/providerconfig.aws.jet.crossplane.io", "request": "/default"}

During the destruction of this single VPC resource, it looks like Workspace.Destroy was successfully executed and managed reconciler logs Successfully requested deletion of external resource in return, and requeues the reconcile key. Upon next reconciliation, we see that only Workspace.Refresh was invoked and Workspace.Plan was not as it's not found in the Terraform state because it has successfully been destroyed. Managed reconciler then logs Successfully deleted managed resource and attempts to remove finalize the resource, which succeeds, and upon next reconciliation of the key, it's no longer found (Cannot get managed resource).

I will also try to reproduce the issue with more VPCs and using some custom logging.

ulucinar commented 2 years ago

I have tried to reproduce the issue in another attempt by creating 10 VPCs and deleting them using a modified Terrajet version which logs the deletion timestamp of the managed resources while initializing a Terraform workspace. I did not encounter any workspace initialization after destruction issue for these 10 resources.

Closing this issue for the moment. If we encounter similar issues again, let's reopen it with the corresponding provider logs and the client-go version used.

muvaf commented 2 years ago

Thanks @ulucinar ! I guess either my observation was wrong due to my environment or the problem has been fixed unknowningly.