Subscription finalizer is blocking namespace deletion

[dsimansk]

Describe the bug
The issue started to manifest itself in knative/client E2E tests running against nightly releases. The tests prepare namespace with labe to inject broker, create, update, delete triggers and finally teardown method deletes the testing namespace. However, the namespace is stuck in terminating state with subscription resources left there.

E2E tests log dump, look for kne2etests8.

Eventing controller log:

{"level":"error","ts":"2020-02-27T15:24:31.809Z","logger":"controller","caller":"controller/controller.go:409","msg":"Reconcile error","commit":"598d52a","error":"inmemorychannels.messaging.knative.dev \"default-kne-trigger\" not found","stacktrace":"knative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).handleErr\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:409\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:395\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:343"}
{"level":"info","ts":"2020-02-27T15:24:31.809Z","logger":"controller","caller":"controller/controller.go:396","msg":"Reconcile failed. Time taken: 1.458989ms.","commit":"598d52a","knative.dev/traceid":"3ab0525c-3eac-43b8-a189-35d09d997ff6","knative.dev/key":"kne2etests0/default-trigger2-036a9c39-d106-42d3-8933-6dc824964bdd"}
{"level":"info","ts":"2020-02-27T15:24:31.810Z","logger":"controller.event-broadcaster","caller":"record/event.go:274","msg":"Event(v1.ObjectReference{Kind:\"Subscription\", Namespace:\"kne2etests0\", Name:\"default-trigger2-036a9c39-d106-42d3-8933-6dc824964bdd\", UID:\"a35c7ee0-916d-4a5d-8aa8-2a67d49448e6\", APIVersion:\"messaging.knative.dev/v1alpha1\", ResourceVersion:\"2316\", FieldPath:\"\"}): type: 'Warning' reason: 'InternalError' inmemorychannels.messaging.knative.dev \"default-kne-trigger\" not found","commit":"598d52a"}
{"level":"warn","ts":"2020-02-27T15:24:32.188Z","logger":"controller","caller":"subscription/subscription.go:329","msg":"GETTING channel","commit":"598d52a","knative.dev/traceid":"57e3c1df-f2b8-4f6c-908c-82f3c75e2756","knative.dev/key":"kne2etests0/default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77","channel":{"kind":"InMemoryChannel","name":"default-kne-trigger","apiVersion":"messaging.knative.dev/v1alpha1"}}
{"level":"error","ts":"2020-02-27T15:24:32.188Z","logger":"controller","caller":"subscription/subscription.go:318","msg":"Error getting channel from lister","commit":"598d52a","knative.dev/traceid":"57e3c1df-f2b8-4f6c-908c-82f3c75e2756","knative.dev/key":"kne2etests0/default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77","channel":{"kind":"InMemoryChannel","name":"default-kne-trigger","apiVersion":"messaging.knative.dev/v1alpha1"},"error":"inmemorychannels.messaging.knative.dev \"default-kne-trigger\" not found","stacktrace":"knative.dev/eventing/pkg/reconciler/subscription.(*Reconciler).trackAndFetchChannel\n\tknative.dev/eventing/pkg/reconciler/subscription/subscription.go:318\nknative.dev/eventing/pkg/reconciler/subscription.(*Reconciler).getChannel\n\tknative.dev/eventing/pkg/reconciler/subscription/subscription.go:332\nknative.dev/eventing/pkg/reconciler/subscription.(*Reconciler).FinalizeKind\n\tknative.dev/eventing/pkg/reconciler/subscription/subscription.go:124\nknative.dev/eventing/pkg/client/injection/reconciler/messaging/v1alpha1/subscription.(*reconcilerImpl).Reconcile\n\tknative.dev/eventing/pkg/client/injection/reconciler/messaging/v1alpha1/subscription/reconciler.go:163\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:394\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:343"}
{"level":"error","ts":"2020-02-27T15:24:32.189Z","logger":"controller","caller":"subscription/reconciler.go:190","msg":"returned an error","commit":"598d52a","knative.dev/traceid":"57e3c1df-f2b8-4f6c-908c-82f3c75e2756","knative.dev/key":"kne2etests0/default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77","targetMethod":"FinalizeKind","error":"inmemorychannels.messaging.knative.dev \"default-kne-trigger\" not found","stacktrace":"knative.dev/eventing/pkg/client/injection/reconciler/messaging/v1alpha1/subscription.(*reconcilerImpl).Reconcile\n\tknative.dev/eventing/pkg/client/injection/reconciler/messaging/v1alpha1/subscription/reconciler.go:190\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:394\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:343"}
{"level":"error","ts":"2020-02-27T15:24:32.189Z","logger":"controller","caller":"controller/controller.go:409","msg":"Reconcile error","commit":"598d52a","error":"inmemorychannels.messaging.knative.dev \"default-kne-trigger\" not found","stacktrace":"knative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).handleErr\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:409\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:395\nknative.dev/eventing/vendor/knative.dev/pkg/controller.(*Impl).Run.func2\n\tknative.dev/eventing/vendor/knative.dev/pkg/controller/controller.go:343"}
{"level":"info","ts":"2020-02-27T15:24:32.189Z","logger":"controller","caller":"controller/controller.go:396","msg":"Reconcile failed. Time taken: 1.325887ms.","commit":"598d52a","knative.dev/traceid":"57e3c1df-f2b8-4f6c-908c-82f3c75e2756","knative.dev/key":"kne2etests0/default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77"}
{"level":"info","ts":"2020-02-27T15:24:32.189Z","logger":"controller.event-broadcaster","caller":"record/event.go:274","msg":"Event(v1.ObjectReference{Kind:\"Subscription\", Namespace:\"kne2etests0\", Name:\"default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77\", UID:\"d1b5385d-d35b-4710-aea6-01a945913e26\", APIVersion:\"messaging.knative.dev/v1alpha1\", ResourceVersion:\"2318\", FieldPath:\"\"}): type: 'Warning' reason: 'InternalError' inmemorychannels.messaging.knative.dev \"default-kne-trigger\" not found","commit":"598d52a"}
E0227 15:24:32.202346       1 event.go:256] Server rejected event '&v1.Event{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77.15f74baaa586e853", GenerateName:"", Namespace:"kne2etests0", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Finalizers:[]string(nil), ClusterName:"", ManagedFields:[]v1.ManagedFieldsEntry(nil)}, InvolvedObject:v1.ObjectReference{Kind:"Subscription", Namespace:"kne2etests0", Name:"default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77", UID:"d1b5385d-d35b-4710-aea6-01a945913e26", APIVersion:"messaging.knative.dev/v1alpha1", ResourceVersion:"2318", FieldPath:""}, Reason:"InternalError", Message:"inmemorychannels.messaging.knative.dev \"default-kne-trigger\" not found", Source:v1.EventSource{Component:"subscription-controller", Host:""}, FirstTimestamp:v1.Time{Time:time.Time{wall:0xbf8e1597941fbc53, ext:315505918496, loc:(*time.Location)(0x2d6dbc0)}}, LastTimestamp:v1.Time{Time:time.Time{wall:0xbf8e15ac0b46cc6f, ext:397357483743, loc:(*time.Location)(0x2d6dbc0)}}, Count:15, Type:"Warning", EventTime:v1.MicroTime{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, Series:(*v1.EventSeries)(nil), Action:"", Related:(*v1.ObjectReference)(nil), ReportingController:"", ReportingInstance:""}': 'events "default-updtrigger-47d25e74-3c12-4db9-8051-aa58b1e25c77.15f74baaa586e853" is forbidden: unable to create new content in namespace kne2etests0 because it is being terminated' (will not retry!)

The exact steps test is going through:
https://github.com/knative/client/blob/master/test/e2e/trigger_test.go#L30

Expected behavior
When namespace is deleted, all belonging resources are successfully deleted.

To Reproduce

1. Minikube with latest nightly preinstalled
2. Clone https://github.com/knative/client
3. Execute ./test/e2e-tests-local.sh -run ^TestBrokerTrigger$
4. Look for namespace kne2etests0 in terminating state

Knative release version
Eventing nightly - v20200227-598d52ae

[dsimansk]

I managed to reproduce the behaviour with plain yamls also:

1. Minikube with latest nightly preinstalled
2. Apply following cmds

kubectl create ns test
kubectl label namespace test knative-eventing-injection=enabled
kubens test

--> wait a bit for broker pods to start

kubectl apply -f https://raw.githubusercontent.com/matzew/knative-eventing-samples/master/03-source_broker/000-ksvc2.yaml 
kubectl apply -f https://raw.githubusercontent.com/matzew/knative-eventing-samples/master/03-source_broker/030-trigger2.yaml

kubectl delete ns test
--> delete op won't finish

3. Check kubectl get all that there's only sub resource left (whole yaml)

NAME                                                                                                 READY     REASON                   AGE
subscription.messaging.knative.dev/default-testevents-trigger-6a42b605-6e45-4b56-a08e-47ea08f0d55e   Unknown   ChannelReferenceFailed   40m

4. kubectl get ns will display test ns in Terminating state
5. After removing the finalizer the stuck subscription is removed and subsequently the namespace also

kubectl patch subscription.messaging.knative.dev/default-testevents-trigger-6a42b605-6e45-4b56-a08e-47ea08f0d55e -p '{"metadata":{"finalizers": []}}' --type=merge

I wonder if that might be related to apiVersion disprepancy from recent change, that seems similar to the following issue. Or a more generic problem related to switch to generated reconciler for subscription.

[lionelvillard]

Thanks! It seems to me it's a duplicate of #2633.

[dsimansk]

Subscriptions cannot be deleted when its associated channel is deleted first. The finalizer is not removed.

Indeed this issue is just another manifestation of the above problem.

@lionelvillard thanks for pointing that out and sorry I should have used search first. :)

/close duplicate

[matzew]

/close

[knative-prow-robot]

@matzew: Closing this issue.

Details

In response to this:

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[AceHack]

How do you work around this issue?

[matzew]

no work ariund, but this is a dup see comments above.

On Fri 28. Feb 2020 at 20:21, Aaron Stainback ***@***.***> wrote: How do you work around this issue? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#2668?email_source=notifications&email_token=AABGPTQZODYGCJ3MIK4E34LRFFP4FA5CNFSM4K45REVKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOENJ2SWY#issuecomment-592685403>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABGPTTFLRY77M44ZG3EINDRFFP4FANCNFSM4K45REVA> .

-- Sent from Gmail Mobile

[dsimansk]

@AceHack
The most straightforward workaround is to remove finalizer, e.g.:

kubectl patch <stale-subscription-name> -p '{"metadata":{"finalizers": []}}' --type=merge  

[nachocano]

@AceHack
The most straightforward workaround is to remove finalizer, e.g.:

kubectl patch <stale-subscription-name> -p '{"metadata":{"finalizers": []}}' --type=merge  

This was fixed last friday here: #2676.
Pull latest master and it should work