Enabling HA and chaosduck for MT Broker yields failures

[mattmoor]

In the context of this PR I tried enabling HA of the mt-broker-controller process and "chaos".

It resulted in these failures during e2e: https://prow.knative.dev/view/gcs/knative-prow/pr-logs/pull/knative_eventing/3565/pull-knative-eventing-integration-tests/1283139079159943170

To reproduce things, sync past #3565 landing (or pull in the PR) and change:

1. ./test/config/chaosduck.yaml: Comment/Remove the -disable=mt-broker-controller flag.
2. ./test/e2e-common.sh: Uncomment the line scale_controlplane mt-broker-controller.

[mattmoor]

/assign @vaikas

[vaikas]

So here are just some rando observations from digging through the (huge number of :) ) logs. I decided to focus on only one of the failures for now, namely this one:

TestEventTransformationForTriggerV1Beta1BrokerV1/InMemoryChannel-messaging.knative.dev/v1beta1

      TestEventTransformationForTriggerV1Beta1BrokerV1/InMemoryChannel-messaging.knative.dev/v1beta1: operation.go:66: Failed to get {Broker eventing.knative.dev/v1beta1}-e2e-eventtransformation-broker ready: timed out waiting for the condition
        knative.dev/eventing/test/lib.(*Client).WaitForResourceReadyOrFail
        	/home/prow/go/src/knative.dev/eventing/test/lib/operation.go:66
        knative.dev/eventing/test/e2e/helpers.EventTransformationForTriggerTestHelper.func1
        	/home/prow/go/src/knative.dev/eventing/test/e2e/helpers/broker_event_transformation_test_helper.go:82
        knative.dev/eventing/test/lib.(*ComponentsTestRunner).RunTests.func1
        	/home/prow/go/src/knative.dev/eventing/test/lib/test_runner.go:70
        testing.tRunner
        	/root/.gvm/gos/go1.14.2/src/testing/testing.go:991
        runtime.goexit
        	/root/.gvm/gos/go1.14.2/src/runtime/asm_amd64.s:1373

  TestEventTransformationForTriggerV1Beta1BrokerV1/InMemoryChannel-messaging.knative.dev/v1beta1: tracker.go:128: Cleaning resource: "e2e-eventtransformation-broker"
        {
          "apiVersion": "eventing.knative.dev/v1",
          "kind": "Broker",
          "metadata": {
            "annotations": {
              "eventing.knative.dev/broker.class": "MTChannelBasedBroker",
              "eventing.knative.dev/creator": "prow-job@knative-tests.iam.gserviceaccount.com",
              "eventing.knative.dev/lastModifier": "prow-job@knative-tests.iam.gserviceaccount.com"
            },
            "creationTimestamp": "2020-07-14T21:03:28Z",
            "generation": 1,
            "name": "e2e-eventtransformation-broker",
            "namespace": "test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2",
            "resourceVersion": "26866",
            "selfLink": "/apis/eventing.knative.dev/v1/namespaces/test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/brokers/e2e-eventtransformation-broker",
            "uid": "bc77835e-5128-4c08-b7b7-49a7fbf6d592"
          },
          "spec": {
            "config": {
              "apiVersion": "v1",
              "kind": "ConfigMap",
              "name": "e2e-eventtransformation-broker",
              "namespace": "test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2"
            }
          },
          "status": {
            "address": {}
          }
        }

So, what's interesting about that is that the Status is empty, aka, not even initialize conditions. As if it's never been reconciled. So after some rudimentary grepping, I've grabbed the leader election relevant bits & the mt-broker-controller log entries that I think would be useful. Let's also make a note of the time this resource was created:

            "creationTimestamp": "2020-07-14T21:03:28Z",

First, the dump for the relevant timeframe.

knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-f7xm8[mt-broker-controller]: I0714 21:03:30.752699       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:03:44.973Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 7.308µs","knative.dev/traceid":"8bf0cc49-837c-4a15-9089-0e2ac675e0e7","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:03:44.974Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 7.35µs","knative.dev/traceid":"9a9f1c1b-094c-4b39-91da-a1c13f9cd7e4","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-tqxbt[mt-broker-controller]: I0714 21:04:00.864486       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: I0714 21:04:30.837896       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:42.728Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:129","msg":"Reconciling","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default","Broker":{"kind":"Broker","apiVersion":"eventing.knative.dev/v1beta1","metadata":{"name":"default","namespace":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2","selfLink":"/apis/eventing.knative.dev/v1beta1/namespaces/test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/brokers/default","uid":"368799dd-370c-4361-aa0a-9413a5fd473d","resourceVersion":"25967","generation":1,"creationTimestamp":"2020-07-14T21:02:56Z","labels":{"eventing.knative.dev/injected":"true"},"annotations":{"eventing.knative.dev/broker.class":"MTChannelBasedBroker","eventing.knative.dev/creator":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller","eventing.knative.dev/lastModifier":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller"},"finalizers":["brokers.eventing.knative.dev"]},"spec":{"config":{"kind":"ConfigMap","namespace":"knative-eventing-03y9gdnogb","name":"config-br-default-channel","apiVersion":"v1"}},"status":{"observedGeneration":1,"conditions":[{"type":"Addressable","status":"Unknown","lastTransitionTime":"2020-07-14T21:03:10Z"},{"type":"FilterReady","status":"Unknown","lastTransitionTime":"2020-07-14T21:03:10Z"},{"type":"IngressReady","status":"Unknown","lastTransitionTime":"2020-07-14T21:03:10Z"},{"type":"Ready","status":"False","lastTransitionTime":"2020-07-14T21:03:10Z","reason":"NoAddress","message":"Channel does not have an address."},{"type":"TriggerChannelReady","status":"False","lastTransitionTime":"2020-07-14T21:03:10Z","reason":"NoAddress","message":"Channel does not have an address."}],"address":{}}}}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:42.734Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:230","msg":"Using channel template = &TypeMeta{Kind:InMemoryChannel,APIVersion:messaging.knative.dev/v1beta1,}","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:42.734Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:139","msg":"Reconciling the trigger channel","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-hqgwl[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:43.057Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 27.281µs","knative.dev/traceid":"b0b9e2b6-dc97-4c02-83de-a9b73ae567ef","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:43.057Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 328.716113ms","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-7mgrz[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:43.057Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 67.868µs","knative.dev/traceid":"b941fa16-e302-414a-b7f0-e0428c6d6b66","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:45.058Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 14.863µs","knative.dev/traceid":"668f2293-c07d-4a71-ae3f-40b2d39d0792","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:45.061Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 8.163µs","knative.dev/traceid":"74daf73d-c700-4874-b436-638185cf0ff4","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-hqgwl[mt-broker-controller]: I0714 21:05:00.941083       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-hqgwl[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:01.191Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:129","msg":"Reconciling","knative.dev/traceid":"82430ffb-39da-41a9-8a8c-ccc23f1b577e","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default","Broker":{"metadata":{"name":"default","namespace":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2","selfLink":"/apis/eventing.knative.dev/v1beta1/namespaces/test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/brokers/default","uid":"368799dd-370c-4361-aa0a-9413a5fd473d","resourceVersion":"29391","generation":1,"creationTimestamp":"2020-07-14T21:02:56Z","labels":{"eventing.knative.dev/injected":"true"},"annotations":{"eventing.knative.dev/broker.class":"MTChannelBasedBroker","eventing.knative.dev/creator":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller","eventing.knative.dev/lastModifier":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller"},"finalizers":["brokers.eventing.knative.dev"]},"spec":{"config":{"kind":"ConfigMap","namespace":"knative-eventing-03y9gdnogb","name":"config-br-default-channel","apiVersion":"v1"}},"status":{"observedGeneration":1,"conditions":[{"type":"Addressable","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"FilterReady","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"IngressReady","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"Ready","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"TriggerChannelReady","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"}],"address":{"url":"http://broker-ingress.knative-eventing-03y9gdnogb.svc.cluster.local/test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}}}}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-hqgwl[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:01.200Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:230","msg":"Using channel template = &TypeMeta{Kind:InMemoryChannel,APIVersion:messaging.knative.dev/v1beta1,}","knative.dev/traceid":"82430ffb-39da-41a9-8a8c-ccc23f1b577e","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-hqgwl[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:01.200Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:139","msg":"Reconciling the trigger channel","knative.dev/traceid":"82430ffb-39da-41a9-8a8c-ccc23f1b577e","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-hqgwl[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:01.200Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 9.026254ms","knative.dev/traceid":"82430ffb-39da-41a9-8a8c-ccc23f1b577e","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:28.189Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 26.11µs","knative.dev/traceid":"77a196d4-cd53-4228-95cb-1d46e4d7b896","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-s8zqp[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:28.192Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 36.53µs","knative.dev/traceid":"ac3889c3-6b3c-4350-8aec-d06f879f3c03","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-7mgrz[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:28.191Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 39.15µs","knative.dev/traceid":"1a53112d-c6b9-4bdc-a2cf-0cf3059d3a72","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: I0714 21:05:30.854239       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:34.270Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:129","msg":"Reconciling","knative.dev/traceid":"06baff92-4db1-49b5-bdc8-9b9071c28120","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default","Broker":{"kind":"Broker","apiVersion":"eventing.knative.dev/v1beta1","metadata":{"name":"default","namespace":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2","selfLink":"/apis/eventing.knative.dev/v1beta1/namespaces/test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/brokers/default","uid":"368799dd-370c-4361-aa0a-9413a5fd473d","resourceVersion":"29391","generation":1,"creationTimestamp":"2020-07-14T21:02:56Z","labels":{"eventing.knative.dev/injected":"true"},"annotations":{"eventing.knative.dev/broker.class":"MTChannelBasedBroker","eventing.knative.dev/creator":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller","eventing.knative.dev/lastModifier":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller"},"finalizers":["brokers.eventing.knative.dev"]},"spec":{"config":{"kind":"ConfigMap","namespace":"knative-eventing-03y9gdnogb","name":"config-br-default-channel","apiVersion":"v1"}},"status":{"observedGeneration":1,"conditions":[{"type":"Addressable","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"FilterReady","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"IngressReady","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"Ready","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"},{"type":"TriggerChannelReady","status":"True","lastTransitionTime":"2020-07-14T21:04:42Z"}],"address":{"url":"http://broker-ingress.knative-eventing-03y9gdnogb.svc.cluster.local/test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}}}}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:34.470Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:230","msg":"Using channel template = &TypeMeta{Kind:InMemoryChannel,APIVersion:messaging.knative.dev/v1beta1,}","knative.dev/traceid":"06baff92-4db1-49b5-bdc8-9b9071c28120","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:34.471Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:139","msg":"Reconciling the trigger channel","knative.dev/traceid":"06baff92-4db1-49b5-bdc8-9b9071c28120","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:05:34.471Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:280","msg":"Creating Channel Object: &{Object:map[apiVersion:messaging.knative.dev/v1beta1 kind:InMemoryChannel metadata:map[annotations:map[eventing.knative.dev/scope:cluster] creationTimestamp:<nil> labels:map[eventing.knative.dev/broker:default eventing.knative.dev/brokerEverything:true] name:default-kne-trigger namespace:test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2 ownerReferences:[map[apiVersion:eventing.knative.dev/v1beta1 blockOwnerDeletion:true controller:true kind:Broker name:default uid:368799dd-370c-4361-aa0a-9413a5fd473d]]]]}","knative.dev/traceid":"06baff92-4db1-49b5-bdc8-9b9071c28120","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"error","ts":"2020-07-14T21:05:34.474Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:283","msg":"Failed to create Channel: test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default-kne-trigger","knative.dev/traceid":"06baff92-4db1-49b5-bdc8-9b9071c28120","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default","error":"inmemorychannels.messaging.knative.dev \"default-kne-trigger\" is forbidden: unable to create new content in namespace test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2 because it is being terminated","stacktrace":"knative.dev/eventing/pkg/reconciler/mtbroker.(*Reconciler).reconcileChannel\n\tknative.dev/eventing/pkg/reconciler/mtbroker/broker.go:283\nknative.dev/eventing/pkg/reconciler/mtbroker.(*Reconciler).reconcileKind\n\tknative.dev/eventing/pkg/reconciler/mtbroker/broker.go:146\nknative.dev/eventing/pkg/reconciler/mtbroker.(*Reconciler).ReconcileKind\n\tknative.dev/eventing/pkg/reconciler/mtbroker/broker.go:106\nknative.dev/eventing/pkg/client/injection/reconciler/eventing/v1beta1/broker.(*reconcilerImpl).Reconcile\n\tknative.dev/eventing/pkg/client/injection/reconciler/eventing/v1beta1/broker/reconciler.go:250\nknative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:465\nknative.dev/pkg/controller.(*Impl).RunContext.func3\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:403"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"error","ts":"2020-07-14T21:05:34.474Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:148","msg":"Problem reconciling the trigger channel","knative.dev/traceid":"06baff92-4db1-49b5-bdc8-9b9071c28120","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default","error":"inmemorychannels.messaging.knative.dev \"default-kne-trigger\" is forbidden: unable to create new content in namespace test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2 because it is being terminated","stacktrace":"knative.dev/eventing/pkg/reconciler/mtbroker.(*Reconciler).reconcileKind\n\tknative.dev/eventing/pkg/reconciler/mtbroker/broker.go:148\nknative.dev/eventing/pkg/reconciler/mtbroker.(*Reconciler).ReconcileKind\n\tknative.dev/eventing/pkg/reconciler/mtbroker/broker.go:106\nknative.dev/eventing/pkg/client/injection/reconciler/eventing/v1beta1/broker.(*reconcilerImpl).Reconcile\n\tknative.dev/eventing/pkg/client/injection/reconciler/eventing/v1beta1/broker/reconciler.go:250\nknative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:465\nknative.dev/pkg/controller.(*Impl).RunContext.func3\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:403"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-qcr9s[mt-broker-controller]: {"level":"error","ts":"2020-07-14T21:05:34.474Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:108","msg":"Problem reconciling broker","knative.dev/traceid":"06baff92-4db1-49b5-bdc8-9b9071c28120","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default","error":"Failed to reconcile trigger channel: inmemorychannels.messaging.knative.dev \"default-kne-trigger\" is forbidden: unable to create new content in namespace test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2 because it is being terminated","stacktrace":"knative.dev/eventing/pkg/reconciler/mtbroker.(*Reconciler).ReconcileKind\n\tknative.dev/eventing/pkg/reconciler/mtbroker/broker.go:108\nknative.dev/eventing/pkg/client/injection/reconciler/eventing/v1beta1/broker.(*reconcilerImpl).Reconcile\n\tknative.dev/eventing/pkg/client/injection/reconciler/eventing/v1beta1/broker/reconciler.go:250\nknative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:465\nknative.dev/pkg/controller.(*Impl).RunContext.func3\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:403"}

Unfortunately the test logs do not have the timestamps to indicate when they timed out (the first blurp), but the tests give a 2 minute timeout to wait for resources to become ready, so it's probably fair to assume that around 21:05:28 test gave up and started tearing things down, resulting in the failure to actuall create the trigger channel because the namespace is being torn down so that sort of checks out timestamp wise.

So, this controller:
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-zbzjs had the lease when the object was created, but there are no entries in the logs for it after 21:03:11... Until... wait for it... it loses the lease to this controller at 21:03:30 to this lucky winner: knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-f7xm8
However, it would appear that it must have been extremely perturbed by something else, or just having a state mandated lunch break since it does absolutely nothing to advance our cause here for 30 seconds, until it too loses its lease righfully so (not pointing fingers, but good riddance...) to our next potential winner at 21:04:00 like so:

knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-f7xm8[mt-broker-controller]: I0714 21:03:30.752699       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:03:44.973Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 7.308µs","knative.dev/traceid":"8bf0cc49-837c-4a15-9089-0e2ac675e0e7","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:03:44.974Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 7.35µs","knative.dev/traceid":"9a9f1c1b-094c-4b39-91da-a1c13f9cd7e4","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-tqxbt[mt-broker-controller]: I0714 21:04:00.864486       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01

I'm super hopeful at this point, so let's see how our next contestant did:

knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-tqxbt[mt-broker-controller]: I0714 21:04:00.864486       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: I0714 21:04:30.837896       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01

Really? All you did was post and gloat to all your friends you actually became the leader, but didn't actually like do anything. zomg... So, now the hopeful leader is knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5 and would you look at that:

knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: I0714 21:04:30.837896       1 leaderelection.go:252] successfully acquired lease knative-eventing-03y9gdnogb/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:42.728Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:129","msg":"Reconciling","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default","Broker":{"kind":"Broker","apiVersion":"eventing.knative.dev/v1beta1","metadata":{"name":"default","namespace":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2","selfLink":"/apis/eventing.knative.dev/v1beta1/namespaces/test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/brokers/default","uid":"368799dd-370c-4361-aa0a-9413a5fd473d","resourceVersion":"25967","generation":1,"creationTimestamp":"2020-07-14T21:02:56Z","labels":{"eventing.knative.dev/injected":"true"},"annotations":{"eventing.knative.dev/broker.class":"MTChannelBasedBroker","eventing.knative.dev/creator":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller","eventing.knative.dev/lastModifier":"system:serviceaccount:knative-eventing-03y9gdnogb:eventing-controller"},"finalizers":["brokers.eventing.knative.dev"]},"spec":{"config":{"kind":"ConfigMap","namespace":"knative-eventing-03y9gdnogb","name":"config-br-default-channel","apiVersion":"v1"}},"status":{"observedGeneration":1,"conditions":[{"type":"Addressable","status":"Unknown","lastTransitionTime":"2020-07-14T21:03:10Z"},{"type":"FilterReady","status":"Unknown","lastTransitionTime":"2020-07-14T21:03:10Z"},{"type":"IngressReady","status":"Unknown","lastTransitionTime":"2020-07-14T21:03:10Z"},{"type":"Ready","status":"False","lastTransitionTime":"2020-07-14T21:03:10Z","reason":"NoAddress","message":"Channel does not have an address."},{"type":"TriggerChannelReady","status":"False","lastTransitionTime":"2020-07-14T21:03:10Z","reason":"NoAddress","message":"Channel does not have an address."}],"address":{}}}}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:42.734Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:230","msg":"Using channel template = &TypeMeta{Kind:InMemoryChannel,APIVersion:messaging.knative.dev/v1beta1,}","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:42.734Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:139","msg":"Reconciling the trigger channel","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-hqgwl[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:43.057Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 27.281µs","knative.dev/traceid":"b0b9e2b6-dc97-4c02-83de-a9b73ae567ef","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}
knative-eventing-03y9gdnogb/mt-broker-controller-7cc899845-svcj5[mt-broker-controller]: {"level":"info","ts":"2020-07-14T21:04:43.057Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 328.716113ms","knative.dev/traceid":"0bb0d4bb-76c0-4df0-b61c-c11a6857a412","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default"}

Forward progress, it appears to have created the trigger channel, and further it appears as expected that the channel it's created is not ready, but alas, that's not the broker we're really interested in, it's the default Broker, and not the one we want...

Ok, so now I'm a bit confused... (well, really been for awhile, but play along)...

There's this curious entry in the logs also, but by this point one could argue the game is over, but probably something we should look into:

knative-eventing-03y9gdnogb/eventing-controller-76f76c5c45-hs2rk[eventing-controller]: {"level":"error","ts":"2020-07-14T21:05:28.193Z","logger":"controller.SourceDucks","caller":"duck/duck.go:76","msg":"runtime object is not convertible to Source duck type: ","commit":"99aa7be","knative.dev/traceid":"e173f2e9-0379-464d-a0c2-4ce1e1277dfd","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker","runtimeObj":null,"stacktrace":"knative.dev/eventing/pkg/reconciler/source/duck.(*Reconciler).Reconcile\n\tknative.dev/eventing/pkg/reconciler/source/duck/duck.go:76\nknative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:465\nknative.dev/pkg/controller.(*Impl).RunContext.func3\n\tknative.dev/pkg@v0.0.0-20200714180919-c49f5b61e264/controller/controller.go:403"}

So I'll pick this up again tomorrow, but as far as I can tell from the logs, no real controller ever stood up and took a crack at this Broker...

[vaikas]

I very well might have sliced the logs wrong, but the fact that we don't see our broker entries in the logs is troubling.
https://github.com/knative/eventing/blob/master/pkg/reconciler/mtbroker/broker.go#L104

func (r *Reconciler) ReconcileKind(ctx context.Context, b *eventingv1.Broker) pkgreconciler.Event {
	triggerChan, err := r.reconcileKind(ctx, b)

https://github.com/knative/eventing/blob/master/pkg/reconciler/mtbroker/broker.go#L126

func (r *Reconciler) reconcileKind(ctx context.Context, b *eventingv1.Broker) (*corev1.ObjectReference, pkgreconciler.Event) {
	logging.FromContext(ctx).Infow("Reconciling", zap.Any("Broker", b))

Would at least me to expect that log entry (which I see printed for the default broker), so for some reason I think our controller does not even get a chance to look at it.

I don't understand why we reconcile the default 8 times (I assume sugar is running, creates it, and the number of reconciles is something we might want to look at in the future, but the point is that no controller ever even looks at the broker that failed). Or I'm just getting tired and missed something :)

vaikas-a01:eventing vaikas$ grep 'test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/e2e-eventtransformation-broker' /tmp/k8s.log.txt | grep Reconciling | wc -l
       0
vaikas-a01:eventing vaikas$ grep 'test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/default' /tmp/k8s.log.txt | grep Reconciling | wc -l
       8

but to make sure I didn't misspell the Broker name:

vaikas-a01:eventing vaikas$ grep 'test-event-transformation-for-trigger-v1-beta1-broker-v1-injtx2/' /tmp/k8s.log.txt | grep Reconciling | wc -l
       8

[mattmoor]

I wanted to trace through things to create a bit of a map to help myself jump around.

When failover happens, this is the path things should take...

1. We see the log statements above from this line of k8s' leaderelection.go
2. That returns to Run() where it calls OnStartedLeading
3. We configure OnStartedLeading here, which calls into Promote
4. Promote calls into the configured PromoteFunc here
5. Which is configured by codegen to call enq on everything in the informer cache here
6. enq is MaybeEnqueueBucketKey from here

I checked that our bkt.Has method should properly claim this key: https://play.golang.org/p/_blxphl6hqM, but this is something we could confirm with debug logging from here. 😞

So... MaybeEnqueueBucketKey should enqueue this key, and by the time that enqueuing happens, IsLeaderFor should return true because PromoteFunc isn't called until the bucket has been registered with the LeaderAwareFuncs here.

I'd love some more logging here, but it should probably be Debugf and there are already a bunch of other statements at that level that'd be useful to see to confirm things are flowing properly (like this and this)...

[mattmoor]

I've created a stacked PR that re-enables HA/chaos for the broker here: #3594

[mattmoor]

Ville and I debugged this some, and what is interesting is that:

1. The leader pods had REALLY deep backlogs in their workqueues: ~125 entries
2. The non-leader pods had virtually empty workqueues.

The processing time for things on the leader were >1s, which smells like client-side rate limiting (we've seen it go as high as ~10s in the past). The default client-side rate limiting in client-go is 5 QPS (burst of 10), which means that we can process at most 5 items from the workqueue per second (though with a latency of 1s and 2 threads, the reality is 2.5x worse than that theoretical bound).

With a depth of 125+ at 5/s it would take at least 25s to process the backlog, and the chaosduck is killing the leader every 30s. The replica that picks up the leader then does a global resync (we are using a single bucket), which means the 125+ items are queued and we start the dance over.

So we went looking for unguarded client calls and found this:

eventing/pkg/reconciler/mtbroker/broker.go

Line 216 in 4f2f82d

cm, err := r.kubeClientSet.CoreV1().ConfigMaps(b.Spec.Config.Namespace).Get(b.Spec.Config.Name, metav1.GetOptions{})

. Every reconciler we do a configmap Get through the kube client, which given this backlog would almost certainly result in client-side rate limiting.

I believe that we didn't see this behavior before the chaosduck because we weren't doing global resyncs every 30s, which is what really makes the controller choke.

Ville is prototyping a change to perform these reads through a configmap lister now, which (🤞 with some luck) will address this and enable us to enable HA/chaos for the MT broker as well. 😈

[vaikas]

I broke out the improvements into their own PR (#3609) so that we can get those in while we continue to debug the issues.

[mattmoor]

Hmm, looking at your PR with debug logging that enables chaos on mt-broker, I still see some reconciles taking >1s, so I wonder whether we still have some paths through ReconcileKind making too many calls 🤔

I see some keys take <1ms:

knative-eventing-bjfbt49d8r/mt-broker-controller-54d9dcc99b-kk4kh[mt-broker-controller]: {"level":"info","ts":"2020-07-19T02:18:24.198Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 833.812µs","knative.dev/traceid":"d78a8a61-5e33-4d54-80f5-4233472a3408","knative.dev/key":"test-event-transformation-for-trigger-v1-beta1-broker-v1-iznqf2/default"}

Where others still take >1s:

knative-eventing-bjfbt49d8r/mt-broker-controller-54d9dcc99b-kk4kh[mt-broker-controller]: {"level":"info","ts":"2020-07-19T02:18:23.844Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:474","msg":"Reconcile succeeded. Time taken: 1.51159081s","knative.dev/traceid":"eb8be07d-592c-4bef-9836-f1fdb3de7cba","knative.dev/key":"test-single-binary-event-for-channel-v1-beta1-in-memory-chfvgg6/default"}

For this last one, there is a large gap (~1.2s) in the logs between it hitting the following path and the ultimate log statement marking the completion of reconciliation for the key 🤔

eventing/pkg/reconciler/mtbroker/broker.go

Lines 152 to 155 in 882d3a4

	logging.FromContext(ctx).Debugw("Trigger Channel does not have an address", zap.Any("triggerChan", triggerChan))
	b.Status.MarkTriggerChannelFailed("NoAddress", "Channel does not have an address.")
	// Ok to return nil for error here, once channel address becomes available, this will get requeued.
	return &chanMan.ref, nil

It's unclear whether this is a function of client-side throttling or whether it is legitimately doing a lot of work in the Trigger portion of the code, which has very little logging 😞