Deleting a ServiceBinding shows a new error in the operator logs (updated 0.6.3 -> 0.6.8)

[pre]

We updated from sap-btp-service-operator 0.6.3 to 0.6.8.

• There's a ServiceBinding in the hana-poc-1 namespace. Removing it with 0.6.3 fails with an actual error, without extra noise about sap-btp-service-operator not finding a secret.
• Attempting to remove this ServiceBinding with 0.6.8 throws an error with a stacktrace about a missing Secret in the operator's namespace (not in the ServiceBinding's namespace).
• Real error why ServiceBinding removal failed can't be seen with 0.6.8 ("Hana instance is stopped" shown in 0.6.3).

The stacktrace gives a hint that this was not a properly handled error, instead something went unexpectedly wrong

When deleting a ServiceBinding with 0.6.3, the controller logs show the actual error without extra noise about a missing Secret:

"msg":"Searching for secret in resource namespace","namespace":"hana-poc-1","name":"sap-btp-service-operator"}
"msg":"Searching for namespace secret in management namespace","namespace":"hana-poc-1","managementNamespace":"sap-btp-operator","name":"sap-btp-service-operator"}
"msg":"Searching for cluster secret","releaseNamespace":"sap-btp-operator","name":"sap-btp-service-operator"}
"msg":"Searching for secret in resource namespace","namespace":"hana-poc-1","name":"sap-btp-service-operator-tls"}
"msg":"Searching for namespace secret in management namespace","namespace":"hana-poc-1","managementNamespace":"sap-btp-operator","name":"sap-btp-service-operator-tls"}
"msg":"Searching for cluster secret","releaseNamespace":"sap-btp-operator","name":"sap-btp-service-operator-tls"}
"msg":"found tls configuration","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","namespace":"hana-poc-1"},"correlation_id":"c1387b85-bc6c-4102-9c71-ef601c76ef2c","subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs":"hana-poc-1"}
"msg":"Current generation is 2 and observed is 2","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","namespace":"hana-poc-1"},"correlation_id":"ab517f9d-6869-4911-8670-56570a81a427","subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs":"hana-poc-1"}
"msg":"getting service instance named subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32 in namespace hana-poc-1 for binding subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs in namespace hana-poc-1","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","namespace":"hana-poc-1"},"correlation_id":"ab517f9d-6869-4911-8670-56570a81a427","subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs":"hana-poc-1"}

When doing the same deletion with 0.6.8, there's a new error about a missing Secret in the operator's namespace. I don't understand why the operator's namespace is searched in the first place. The stacktrace gives a hint that this was not a correctly handled error:

"msg":"found tls configuration","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","na
"msg":"Deleting binding with id 7709b31e-2c00-4fe7-8b0e-ab32868bfb84 from SM","servicebinding":{"name":"subscriber-tenant-2819b4a9-9
"msg":"Deleting binding async","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","nam
"msg":"setting inProgress conditions: reason: DeleteInProgress, message:ServiceBinding is being deleted, generation: 2","servicebind
"msg":"updating ServiceBinding status","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pv
"msg":"Current generation is 2 and observed is 2","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-b
"msg":"getting service instance named subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32 in namespace hana-poc-1 for binding sub
"msg":"Searching for secret sap-btp-service-operator in namespace hana-poc-1"}
"msg":"Searching for secret hana-poc-1-sap-btp-service-operator in management namespace sap-btp-operator"}
"msg":"Could not fetch secret hana-poc-1-sap-btp-service-operator from management namespace sap-btp-operator","error":"Secret \"hana-poc-1-sap-btp-service-operator\" not found","stacktrace":"github.com/SAP/sap-btp-service-operator/internal/utils.(*secretClient).getSecretFromManagementNamespace\n\t/workspace/internal/utils/secret_resolver.go:67\ngithub.com/SAP/sap-btp-service-operator/internal/utils.(*secretClient).getSecretForResource\n\t/workspace/internal/utils/secret_resolver.go:92\ngithub.com/SAP/sap-btp-service-operator/internal/utils.GetSecretForResource\n\t/workspace/internal/utils/secret_resolver.go:58\ngithub.com/SAP/sap-btp-service-operator/internal/utils.GetSMClient\n\t/workspace/internal/utils/sm_utils.go:31\ngithub.com/SAP/sap-btp-service-operator/controllers.(*ServiceBindingReconciler).delete\n\t/workspace/controllers/servicebinding_controller.go:325\ngithub.com/SAP/sap-btp-service-operator/controllers.(*ServiceBindingReconciler).Reconcile\n\t/workspace/controllers/servicebinding_controller.go:124\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:114\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:311\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:261\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:222"}
"msg":"Searching for cluster secret sap-btp-service-operator in releaseNamespace sap-btp-operator"}
"msg":"Searching for secret sap-btp-service-operator-tls in namespace hana-poc-1"}
"msg":"Searching for secret hana-poc-1-sap-btp-service-operator-tls in management namespace sap-btp-operator"}
"msg":"Could not fetch secret hana-poc-1-sap-btp-service-operator-tls from management namespace sap-btp-operator","error":"Secret \"hana-poc-1-sap-btp-service-operator-tls\" not found","stacktrace":"github.com/SAP/sap-btp-service-operator/internal/utils.(*secretClient).getSecretFromManagementNamespace\n\t/workspace/internal/utils/secret_resolver.go:67\ngithub.com/SAP/sap-btp-service-operator/internal/utils.(*secretClient).getSecretForResource\n\t/workspace/internal/utils/secret_resolver.go:92\ngithub.com/SAP/sap-btp-service-operator/internal/utils.GetSecretForResource\n\t/workspace/internal/utils/secret_resolver.go:58\ngithub.com/SAP/sap-btp-service-operator/internal/utils.GetSMClient\n\t/workspace/internal/utils/sm_utils.go:61\ngithub.com/SAP/sap-btp-service-operator/controllers.(*ServiceBindingReconciler).delete\n\t/workspace/controllers/servicebinding_controller.go:325\ngithub.com/SAP/sap-btp-service-operator/controllers.(*ServiceBindingReconciler).Reconcile\n\t/workspace/controllers/servicebinding_controller.go:124\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Reconcile\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:114\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:311\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:261\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:222"}
"msg":"Searching for cluster secret sap-btp-service-operator-tls in releaseNamespace sap-btp-operator"}
"msg":"found tls configuration","servicebinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","namespace":"hana-poc-1"},"
"msg":"resource is in progress, found operation url /v1/service_bindings/7709b31e-2c00-4fe7-8b0e-ab32868bfb84/operations/92ef0bef-8e51-4875-a05e-0dd79c86b2fa",

At the time of writing, I am not yet sure if the deletion will succeed at all with 0.6.8. With 0.6.8 I only see the "error":"Secret \"hana-poc-1-sap-btp-service-operator\" not found but no mention of the following which is visible with 0.6.3

{"level":"error","ts":"2024-10-24T07:47:23Z","msg":"Reconciler error","controller":"servicebinding","controllerGroup":"services.cloud.sap.com","controllerKind":"ServiceBinding","ServiceBinding":{"name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","namespace":"hana-poc-1"},"namespace":"hana-poc-1","name":"subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs","reconcileID":"4cfc3fe5-17e0-4d9d-9976-99199f7aba41","error":"Async unbind operation failed, errors: {\"error\":\"BrokerError\",\"description\":\"failed polling operation for binding with id 7709b31e-2c00-4fe7-8b0e-ab32868bfb84 and name subscriber-tenant-2819b4a9-994f-4ad7-83c0-22d1607edd32-binding-64pvqs due to polling last operation error: Failed to drop service binding '7709b31e-2c00-4fe7-8b0e-ab32868bfb84' for instance '34ef927e-29f5-4ef4-8b85-d4e36285d90e' on database '5e481f2b-22a2-4430-825e-6d60f8b929bf' (5e481f2b-22a2-4430-825e-6d60f8b929bf.hana.prod-eu12.hanacloud.ondemand.com:443), because of: Failed to open connection to the database, because of: Failed to get connection for database '5e481f2b-22a2-4430-825e-6d60f8b929bf' (5e481f2b-22a2-4430-825e-6d60f8b929bf.hana.prod-eu12.hanacloud.ondemand.com:443), because of: SAP DBTech JDBC: [1890]: HANA Database instance is stopped\"}","stacktrace":"sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).reconcileHandler\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:324\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).processNextWorkItem\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:265\nsigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller).Start.func2.2\n\t/go/pkg/mod/sigs.k8s.io/[email protected]/pkg/internal/controller/controller.go:226"}

That said, with 0.6.8 and the error about the missing Secret, the .status of the ServiceBinding is not updated at all. The latest status is still a rate limit error when trying with 0.6.3. Here is the full .status:

status:
  bindingID: 7709b31e-2c00-4fe7-8b0e-ab32868bfb84
  conditions:
  - lastTransitionTime: "2024-06-29T00:59:25Z" # <-- months ago
    message: 'ServiceBinding deletion failed: The allowed request limit of 20 requests
      has been reached please try again later'
    observedGeneration: 2
    reason: DeleteFailed
    status: "False"
    type: Succeeded
  - lastTransitionTime: "2024-08-28T00:00:14Z" # <-- months ago
    message: ""
    reason: NotProvisioned
    status: "False"
    type: Ready
  - lastTransitionTime: "2024-10-24T07:51:02Z" # <-- 55 minutes ago !!
    message: 'ServiceBinding deletion failed: The allowed request limit of 20 requests
      has been reached please try again later'
    observedGeneration: 2
    reason: DeleteFailed
    status: "True"
    type: Failed

Notice that the latest status is 55 minutes ago, even though sap-btp-service-operator 0.6.8 failed with the missing Secret error just minutes ago. I also restarted sap-btp-service-operator 0.6.8 multiple times during these 55 minutes, and the .status did not change.

UPDATE:

• After patiently waiting for 1 hour since the latest rate limit message in .status, the ServiceBinding was successfully deleted (Hana instance was started in order to successfully remove the binding).

TL;DR

• The timestamp of .status in the ServiceBinding should be updated when a newer rate limit is hit.
• The real cause of the failure is masked under the rate limit error in .status (while still keeping the months-old obsolete errors there).
  • Real cause of a deletion failed error is masked under a rate limit error #476
• The error with a stacktrace about a missing Secret in the operator's namespace is misleading and did not appear in 0.6.3.

[I065450]

Hi @pre
The new error in the logs will be removed in the next version.
#470

Regards,
Naama