Bug: APIM Product Deletion broken

[anandpatra18]

Describe the bug

APIM product deletion feature broken. Whenever we try to delete the resource , it goes into failed state with a 400:Bad request error with no description. Seems like the deletion feature has not been implemented at all.

Azure Service Operator Version: v2.10.0

Expected behavior

A successful deletion action of the product

To Reproduce

Create a product through ASO and then try deleting it

[theunrepentantgeek]

Can you supply us with the ASO logs showing the 400 error? We have automated tests that create, update and delete APIM resources, so I'm curious what I can glean from the context of those logs. It's possible we missed something in those tests - or possibly there's another factor involved. (We have seen other resources that are sensitive about the order of deletion, but usually ASO gets there through retries.)

[anandpatra18]

PFA the log i see on the ASO for this action

failed to delete product "local-poc-helm-test": DELETE
https://management.azure.com/subscriptions/XXXXXXX-XXXXX-XXXX-XXXX-XXXXXXX/resourceGroups/rg-alpha-compute-dev/providers/Microsoft.ApiManagement/service/apim-alpha-dev/products/local-poc-helm-test

    --------------------------------------------------------------------------------

    RESPONSE 400: 400 Bad Request

    ERROR CODE UNAVAILABLE

    --------------------------------------------------------------------------------

    Response contained no body

    --------------------------------------------------------------------------------

[super-harsh]

Hi @anandpatra18, I tried to repro this issue (logs below). Although the DELETE action succeeds successfully for me.
Could you please provide us more information on what API version are you using out of 20220801 and 20230501preview. Also, it'd be helpful if you could share the resource YAMLs as well please.

I tried

apimanagement_product "msg"="Reconcile invoked" name="asotest-product2-ocqsvh" namespace="aso-test-apimanagement-20230501preview-crud" kind="&TypeMeta{Kind:Product,APIVersion:apimanagement.azure.com/v1api20220801storage,}" resourceVersion="1534" generation=2 uid="4512fe96-9cbd-4e28-8209-afda7a2848ec" ownerReferences=[]v1.OwnerReference{v1.OwnerReference{APIVersion:"apimanagement.azure.com/v1api20220801storage", Kind:"Service", Name:"asotest-apimanagementv2-twykac", UID:"cd6cc816-a27e-41a4-be29-05e5863c432a", Controller:(*bool)(nil), BlockOwnerDeletion:(*bool)(nil)}} creationTimestamp="2024-12-12 03:10:17 +0530 IST" deletionTimestamp="2024-12-12 03:11:29 +0530 IST" finalizers=[]string{"serviceoperator.azure.com/finalizer"} annotations=map[string]string{"serviceoperator.azure.com/latest-reconciled-generation":"1", "serviceoperator.azure.com/operator-namespace":"azureserviceoperator-system", "serviceoperator.azure.com/resource-id":"/subscriptions/{Redacted}/resourceGroups/asotest-rg-zlmwur/providers/Microsoft.ApiManagement/service/asotest-apimanagementv2-twykac/products/asotest-product2-ocqsvh"} conditions="[Condition [Ready], Status = \"True\", ObservedGeneration = 1, Severity = \"\", Reason = \"Succeeded\", Message = \"\", LastTransitionTime = \"2024-12-12 03:10:30 +0530 IST\"]" owner="asotest-apimanagementv2-twykac, Group/Kind: apimanagement.azure.com/Service"
apimanagement_product "msg"="Determined Delete action" name="asotest-product2-ocqsvh" namespace="aso-test-apimanagement-20230501preview-crud" azureName="asotest-product2-ocqsvh" action="BeginDelete"
apimanagement_product "msg"="Starting delete of resource" name="asotest-product2-ocqsvh" namespace="aso-test-apimanagement-20230501preview-crud" azureName="asotest-product2-ocqsvh"
apimanagement_product "msg"="Running customized deletion" name="asotest-product2-ocqsvh" namespace="aso-test-apimanagement-20230501preview-crud" azureName="asotest-product2-ocqsvh"
apimanagement_product "msg"="Successfully issued DELETE to Azure" name="asotest-product2-ocqsvh" namespace="aso-test-apimanagement-20230501preview-crud" azureName="asotest-product2-ocqsvh"
apimanagement_product "msg"="Delete succeeded, removing finalizer" name="asotest-product2-ocqsvh" namespace="aso-test-apimanagement-20230501preview-crud"

[anandpatra18]

Hi @super-harsh ,
Thank you for your response.
I am using the 20230501preview version and the resource yaml is the one below

---

apiVersion: apimanagement.azure.com/v1api20230501preview
kind: Product
metadata:
name: "gc-generic-product-deltatest"
namespace: "abc"
spec:
approvalRequired: {{ default "true" .approvalRequired }}
azureName: "gc-generic-product-deltatest"
description: "gc-generic-product-deltatest"
displayName: "gc-generic-product-deltatest"
state: {{ default "published" .state }}
subscriptionRequired: true
owner:
armId: "subscriptions/XXXXXXX-XXXXX-XXXX-XXXX-XXXXXXX/resourceGroups/rg-alpha-compute-dev/providers/Microsoft.ApiManagement/service/apim-alpha-dev"

[super-harsh]

Hi @anandpatra18, I just tested this out. I still don't see any issues in deletion. Could you please share the logs as well?

Scenarios tested:

• Basic

1. Create APIM Service
2. Create APIM Product with provided yaml above
3. Issue Delete for APIM Product

• With other resources

1. Create APIM Service
2. Create APIM Product with provided yaml above
3. Create APIM API
4. Create APIM APIVersionSet
5. Create APIM Product API
6. Issue Delete for APIM Product

Below are the logs from controller:

I1217 05:26:09.868788       1 common.go:67] "Reconcile invoked" logger="controllers.apimanagement_product" name="sampleapimproduct-harshdsingh" namespace="default" kind="&TypeMeta{Kind:Product,APIVersion:apimanagement.azure.com/v1api20220801storage,}" resourceVersion="29721" generation=2 uid="19db5450-1e31-4cb3-928a-a1131a0b6f17" ownerReferences=[{"apiVersion":"apimanagement.azure.com/v1api20220801storage","kind":"Service","name":"sampleapimservice-harshdsingh","uid":"ac7bcc1f-dd0f-476b-9b90-c0a604f80795"}] creationTimestamp="2024-12-17 04:25:42 +0000 UTC" deletionTimestamp="2024-12-17 05:26:09 +0000 UTC" finalizers=["serviceoperator.azure.com/finalizer"] annotations={"serviceoperator.azure.com/latest-reconciled-generation":"1","serviceoperator.azure.com/operator-namespace":"azureserviceoperator-system","serviceoperator.azure.com/resource-id":"/subscriptions/{Redacted}/resourceGroups/aso-rg-harshdsingh-test/providers/Microsoft.ApiManagement/service/sampleapimservice-harshdsingh/products/sampleapimproduct-harshdsingh"} conditions="[Condition [Ready], Status = \"True\", ObservedGeneration = 1, Severity = \"\", Reason = \"Succeeded\", Message = \"\", LastTransitionTime = \"2024-12-17 04:25:46 +0000 UTC\"]" owner="sampleapimservice-harshdsingh, Group/Kind: apimanagement.azure.com/Service"
I1217 05:26:09.868881       1 azure_generic_arm_reconciler_instance.go:90] "Determined Delete action" logger="controllers.apimanagement_product" name="sampleapimproduct-harshdsingh" namespace="default" azureName="sampleapimproduct-harshdsingh" action="BeginDelete"
I1217 05:26:09.868891       1 azure_generic_arm_reconciler_instance.go:206] "Starting delete of resource" logger="controllers.apimanagement_product" name="sampleapimproduct-harshdsingh" namespace="default" azureName="sampleapimproduct-harshdsingh"
I1217 05:26:09.868901       1 deleter.go:52] "Running customized deletion" logger="controllers.apimanagement_product" name="sampleapimproduct-harshdsingh" namespace="default" azureName="sampleapimproduct-harshdsingh"
I1217 05:26:09.871273       1 recorder.go:104] "Using credential from \"azureserviceoperator-system/aso-controller-settings\"" logger="events" type="Normal" object={"kind":"Product","namespace":"default","name":"sampleapimproduct-harshdsingh","uid":"19db5450-1e31-4cb3-928a-a1131a0b6f17","apiVersion":"apimanagement.azure.com/v1api20220801storage","resourceVersion":"29721"} reason="CredentialFrom"
I1217 05:26:09.871291       1 recorder.go:104] "Starting delete of resource" logger="events" type="Normal" object={"kind":"Product","namespace":"default","name":"sampleapimproduct-harshdsingh","uid":"19db5450-1e31-4cb3-928a-a1131a0b6f17","apiVersion":"apimanagement.azure.com/v1api20220801storage","resourceVersion":"29721"} reason="BeginDelete"
2024/12/17 05:26:09 http: TLS handshake error from 10.244.2.51:43952: EOF
I1217 05:26:10.873482       1 azure_generic_arm_reconciler_instance.go:828] "Successfully issued DELETE to Azure" logger="controllers.apimanagement_product" name="sampleapimproduct-harshdsingh" namespace="default" azureName="sampleapimproduct-harshdsingh"
I1217 05:26:10.873501       1 generic_reconciler.go:264] "Delete succeeded, removing finalizer" logger="controllers.apimanagement_product" name="sampleapimproduct-harshdsingh" namespace="default"

[bharath2602]

Hi @super-harsh, Please find below the controller logs captured when attempting to delete the product.

I1218 05:41:50.110832 1 azure_generic_arm_reconciler_instance.go:90] "Determined Delete action" logger="controllers.apimanagement_product" name="gc-generic-product-alphatest" namespace="grandcentral" azureName="gc-generic-product-alphatest" action="BeginDelete"
I1218 05:41:50.110854 1 azure_generic_arm_reconciler_instance.go:206] "Starting delete of resource" logger="controllers.apimanagement_product" name="gc-generic-product-alphatest" namespace="grandcentral" azureName="gc-generic-product-alphatest"
I1218 05:41:50.110873 1 deleter.go:52] "Running customized deletion" logger="controllers.apimanagement_product" name="gc-generic-product-alphatest" namespace="grandcentral" azureName="gc-generic-product-alphatest"
I1218 05:41:50.110993 1 recorder.go:104] "Using credential from "azureserviceoperator-system/aso-controller-settings"" logger="events" type="Normal" object={"kind":"Product","namespace":"grandcentral","name":"gc-generic-product-alphatest","uid":"50db8794-c3df-4da8-9c65-d00eef803bdd","apiVersion":"apimanagement.azure.com/v1api20220801storage","resourceVersion":"472726586"} reason="CredentialFrom"
I1218 05:41:50.111182 1 recorder.go:104] "Starting delete of resource" logger="events" type="Normal" object={"kind":"Product","namespace":"grandcentral","name":"gc-generic-product-alphatest","uid":"50db8794-c3df-4da8-9c65-d00eef803bdd","apiVersion":"apimanagement.azure.com/v1api20220801storage","resourceVersion":"472726586"} reason="BeginDelete"
E1218 05:41:50.352674 1 azure_generic_arm_reconciler_instance.go:94] "Error during Delete" err=<
failed to delete product "gc-generic-product-alphatest": DELETE https://management.azure.com/subscriptions/xxxxxxx-xxxxxx-xxxxxxx/resourceGroups/rg-alpha-compute-dev/providers/Microsoft.ApiManagement/service/apim-alpha-dev/products/gc-generic-product-alphatest
--------------------------------------------------------------------------------
RESPONSE 400: 400 Bad Request
ERROR CODE UNAVAILABLE
--------------------------------------------------------------------------------
Response contained no body
--------------------------------------------------------------------------------
logger="controllers.apimanagement_product" name="gc-generic-product-alphatest" namespace="grandcentral" azureName="gc-generic-product-alphatest" action="BeginDelete"
E1218 05:41:50.352791 1 generic_reconciler.go:376] "Encountered error impacting Ready condition" err=<
Reason: Failed, Severity: Warning, RetryClassification: RetrySlow, Cause: failed to delete product "gc-generic-product-alphatest": DELETE https://management.azure.com/subscriptions/xxxxxxx-xxxxxx-xxxxxxx/resourceGroups/rg-alpha-compute-dev/providers/Microsoft.ApiManagement/service/apim-alpha-dev/products/gc-generic-product-alphatest
--------------------------------------------------------------------------------
RESPONSE 400: 400 Bad Request
ERROR CODE UNAVAILABLE
--------------------------------------------------------------------------------
Response contained no body
--------------------------------------------------------------------------------
logger="controllers.apimanagement_product" name="gc-generic-product-alphatest" namespace="grandcentral"
I1218 05:41:50.353054 1 recorder.go:104] "failed to delete product "gc-generic-product-alphatest": DELETE https://management.azure.com/subscriptions/xxxxxxx-xxxxxx-xxxxxxx/resourceGroups/rg-alpha-compute-dev/providers/Microsoft.ApiManagement/service/apim-alpha-dev/products/gc-generic-product-alphatest\n--------------------------------------------------------------------------------\nRESPONSE 400: 400 Bad Request\nERROR CODE UNAVAILABLE\n--------------------------------------------------------------------------------\nResponse contained no body\n--------------------------------------------------------------------------------\n" logger="events" type="Warning" object={"kind":"Product","namespace":"grandcentral","name":"gc-generic-product-alphatest","uid":"50db8794-c3df-4da8-9c65-d00eef803bdd","apiVersion":"apimanagement.azure.com/v1api20220801storage","resourceVersion":"472726586"} reason="DeleteActionError"

[tomkerkhove]

Here is the query I am seeing from the backend:

Internal Query

PreciseTimeStamp	httpMethod	uri	response	userAgent
2024-11-30T21:26:19.2896434Z	DELETE	https://<redacted>/subscriptions/<redacted>/resourceGroups/<redacted>/providers/Microsoft.ApiManagement/service/<redacted>/products/<redacted>?api-version=2021-08-01&deleteSubscriptions=true	400	azsdk-go-armapimanagement.ProductClient/v1.1.1 (go1.22.8; linux) aso-controller/v2.10.0

The problem is that it's using 2021-08-01 and not 2023-05-01-preview

[theunrepentantgeek]

I wonder if the custom extension that implements deletion for APIM Product is using an older version of the azure-sdk-for-go and that's the source of the problem. Though that doesn't explain why @super-harsh can't reproduce it.

[matthchr]

@tomkerkhove - I've written a query based on the one you shared which shows that there aren't any instances of this request failing with the API version in question, and there seem to be a lot of successes. Internal Query.

Is it possible that at some point in the past, 2021-08-01 didn't work everywhere? I can even see some requests coming from ASO that succeeded, so I am thinking that this works now.

@anandpatra18 - can you still reproduce this issue?

[anandpatra18]

HI Mathew, Yes we can reproduce it very consistently when the min api version of the APIM instance was set to 2022-08-01, but based on Tom's advise we updated the min api version of the APIM version to 2021-08-01 and now it works as expected. I think Tom's ask is to investigate why it doesn't work irrespective of the min api version being set for the APIM instance, as ll the other CRDs worked as expected with the higher min api version except the Products CRD. Regards Anand

…

On Mon, 10 Feb 2025 at 22:40, Matthew Christopher ***@***.***> wrote: @tomkerkhove <https://github.com/tomkerkhove> - I've written a query based on the one you shared which shows that there aren't any instances of this request failing with the API version in question, and there seem to be a lot of successes. Internal Query <https://dataexplorer.azure.com/clusters/apim/databases/APIMProd?query=H4sIAAAAAAAAA21QQU7DMBC85xWWTyAlOC0cOJBDJHKCSEjtB4wzbRYltuXdFA48HrcSBUGPO7M7OzPtNF3p3nq7xwwvT5H0dfGp3kckqFEk9pAxDKpplH7snrttp8%2F0kki54MWSZ6VNTy4FDju5aSP9SBpGOpCD0cr64e9RTGFYnPBFdsAEwWZ5ZZcoCgXPjaQFl3ZtpOqAxHmpWdfrVVXfV%2FVKF8Z8203gmBVwzHJX18U%2F%2FEHdnuDs6Q1O1EuCI8aWZmzEzrH8VUh5fF%2Beb%2FOYY7b7nLdU%2BHA4ue3BnFv4AmlEb8ZkAQAA> . Is it possible that at some point in the past, 2021-08-01 didn't work everywhere? I can even see some requests coming from ASO that succeeded, so I am thinking that this works now. @anandpatra18 <https://github.com/anandpatra18> - can you still reproduce this issue? — Reply to this email directly, view it on GitHub <#4485 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/BBU7EA37ZMYMMNRNVHIRPU32PEMFXAVCNFSM6AAAAABS7WGU5CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDMNBZGMYDENJXGQ> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[tomkerkhove]

2021-08-01 is a deprecated API version; so that is why people set higher API versions to be enforced. It turns out that the product deletion, however, depends on this which is what needs to be fixed.