search

knative / eventing

Event-driven application platform for Kubernetes
https://knative.dev/docs/eventing
Apache License 2.0
1.42k stars 595 forks source link

Enabling HA and chaosduck for MT Broker yields failures #3591

Closed mattmoor closed 4 years ago

mattmoor commented 4 years ago

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 commented 4 years ago

/assign @vaikas

vaikas commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

I've created a stacked PR that re-enables HA/chaos for the broker here: https://github.com/knative/eventing/pull/3594

mattmoor commented 4 years ago

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: https://github.com/knative/eventing/blob/4f2f82dccba1c61b7e86391f407ff5f7519ecdac/pkg/reconciler/mtbroker/broker.go#L216. 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 commented 4 years ago

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 commented 4 years ago

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 🤔
https://github.com/knative/eventing/blob/882d3a4d8be7851fe48b10585411ecd5b379ff99/pkg/reconciler/mtbroker/broker.go#L152-L155

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 😞

mattmoor commented 4 years ago

I'm kind of concerned about the fanout in the Broker controller having unbounded arity and performing a virtually unbounded number of writes under certain circumstances 🤔

vaikas commented 4 years ago

I'm kind of concerned also about these? So, unless I'm mistaken these will count towards the API client quota that we believed was causing issues. If that's indeed the case, seeing bursts like these would basically almost even cap the default burst quota unless I'm misunderstanding. That's 8 API ops within a second and defaults are 5/10. Is that right @mattmoor ?

I0722 15:39:16.317842       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
I0722 15:39:16.317894       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
I0722 15:39:16.321246       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
I0722 15:39:16.321325       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
I0722 15:39:16.325829       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
I0722 15:39:16.325888       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
I0722 15:39:16.331923       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
I0722 15:39:16.331978       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/coordination.k8s.io/v1/namespaces/knative-eventing/leases/mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.reconciler.00-of-01
vaikas commented 4 years ago

I've been wading through the HTTP logs to figure out if there are any unnecessary calls for us. So far at least if a Controller gets killed and there is a broker / trigger in the ready state (so, also messaging resources, etc.) there are no unnecessary API calls that I can see. As in, there are none. The one exception is the get to imc, which I believe to be because there's no lister yet in the tracker and it sets up the informer / lister for it.

I0722 16:17:08.356181       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/messaging.knative.dev/v1beta1/inmemorychannels
I0722 16:17:08.356237       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/messaging.knative.dev/v1beta1/inmemorychannels

I'm less concerned about those, since these should happen only when there are new kinds of channels and none in the steady state.

I'll keep digging, but at least that part is encouraging.

vaikas commented 4 years ago

Ok, it's not quite as bad, so we don't actually exhaust our entire 5/sec api quota, just 4/sec :) https://github.com/knative/pkg/issues/1541

lionelvillard commented 4 years ago

to be clear, this is 5/sec api quota per host, right?

mattmoor commented 4 years ago

@lionelvillard yes. It's cooperative and we raise it under certain circumstances, but that's the default.

vaikas commented 4 years ago

I thought it was per client and not per host? If I create two clients from the same host they could have different quotas?

mattmoor commented 4 years ago

Yes, I was interpreting what @lionelvillard was asking as "per-replica" vs. all the replicas collectively.

I believe that this may even be the quota per clientset, but it is possible that the sharing of rest.Config shares the quota.

vaikas commented 4 years ago

Yeah, just wanted to make sure I didn't misremember :)

vaikas commented 4 years ago

Just more debugging and something that I'm finding interesting, so jotting it down here, and making sure I'm not misreading something. https://storage.googleapis.com/knative-prow/pr-logs/pull/knative_eventing/3599/pull-knative-eventing-integration-tests/1286205844102320129/artifacts/k8s.log.txt

Here's a snippet for a failed test.

knative-eventing-08wuioh141/mt-broker-controller-85c8ff4c99-4mj49[mt-broker-controller]: {"level":"debug","ts":"2020-07-23T08:08:30.517Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:458","msg":"Processing from queue test-trigger-dependency-annotation-z2ml5/default (depth: 69)"}

knative-eventing-08wuioh141/mt-broker-controller-85c8ff4c99-4mj49[mt-broker-controller]: {"level":"info","ts":"2020-07-23T08:08:31.031Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:127","msg":"Reconciling","knative.dev/traceid":"ba502e99-4897-47da-8b27-1368b7ed6aa1","knative.dev/key":"test-trigger-dependency-annotation-z2ml5/default","Broker":{"metadata":{"name":"default","namespace":"test-trigger-dependency-annotation-z2ml5","selfLink":"/apis/eventing.knative.dev/v1/namespaces/test-trigger-dependency-annotation-z2ml5/brokers/default","uid":"fec31aa1-8baf-4b28-9c3d-0d07bd57d2bb","resourceVersion":"23808","generation":1,"creationTimestamp":"2020-07-23T08:08:22Z","labels":{"eventing.knative.dev/injected":"true"},"annotations":{"eventing.knative.dev/broker.class":"MTChannelBasedBroker","eventing.knative.dev/creator":"system:serviceaccount:knative-eventing-08wuioh141:eventing-controller","eventing.knative.dev/lastModifier":"system:serviceaccount:knative-eventing-08wuioh141:eventing-controller"},"finalizers":["brokers.eventing.knative.dev"]},"spec":{"config":{"kind":"ConfigMap","namespace":"knative-eventing-08wuioh141","name":"config-br-default-channel","apiVersion":"v1"}},"status":{"conditions":[{"type":"Addressable","status":"Unknown","lastTransitionTime":"2020-07-23T08:08:31Z"},{"type":"FilterReady","status":"Unknown","lastTransitionTime":"2020-07-23T08:08:31Z"},{"type":"IngressReady","status":"Unknown","lastTransitionTime":"2020-07-23T08:08:31Z"},{"type":"Ready","status":"Unknown","lastTransitionTime":"2020-07-23T08:08:31Z","reason":"NewObservedGenFailure","message":"unsuccessfully observed a new generation"},{"type":"TriggerChannelReady","status":"Unknown","lastTransitionTime":"2020-07-23T08:08:31Z"}],"address":{}}}}

knative-eventing-08wuioh141/mt-broker-controller-85c8ff4c99-4mj49[mt-broker-controller]: {"level":"debug","ts":"2020-07-23T08:08:31.237Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"mtbroker/broker.go:152","msg":"Trigger Channel does not have an address","knative.dev/traceid":"ba502e99-4897-47da-8b27-1368b7ed6aa1","knative.dev/key":"test-trigger-dependency-annotation-z2ml5/default","triggerChan":{"kind":"InMemoryChannel","apiVersion":"messaging.knative.dev/v1beta1","metadata":{"name":"default-kne-trigger","namespace":"test-trigger-dependency-annotation-z2ml5","selfLink":"/apis/messaging.knative.dev/v1beta1/namespaces/test-trigger-dependency-annotation-z2ml5/inmemorychannels/default-kne-trigger","uid":"ffdd2e54-bb7d-4047-9e6a-dbb1363e64ef","resourceVersion":"23820","generation":1,"creationTimestamp":"2020-07-23T08:08:31Z","labels":{"eventing.knative.dev/broker":"default","eventing.knative.dev/brokerEverything":"true"},"annotations":{"eventing.knative.dev/scope":"cluster","messaging.knative.dev/creator":"system:serviceaccount:knative-eventing-08wuioh141:eventing-controller","messaging.knative.dev/lastModifier":"system:serviceaccount:knative-eventing-08wuioh141:eventing-controller","messaging.knative.dev/subscribable":"v1beta1"},"ownerReferences":[{"apiVersion":"eventing.knative.dev/v1","kind":"Broker","name":"default","uid":"fec31aa1-8baf-4b28-9c3d-0d07bd57d2bb","controller":true,"blockOwnerDeletion":true}]},"spec":{},"status":{}}}

knative-eventing-08wuioh141/mt-broker-controller-85c8ff4c99-4mj49[mt-broker-controller]: {"level":"info","ts":"2020-07-23T08:08:32.137Z","logger":"mt-broker-controller.knative.dev-eventing-pkg-reconciler-mtbroker.Reconciler","caller":"controller/controller.go:496","msg":"Reconcile succeeded. Time taken: 1.619467508s","knative.dev/traceid":"ba502e99-4897-47da-8b27-1368b7ed6aa1","knative.dev/key":"test-trigger-dependency-annotation-z2ml5/default"}

clean it up a little bit and shortening, check me on this one :)

23T08:08:30.517Z - Processing from queue
23T08:08:31.031Z - MT Broker starts ReconcileKind
23T08:08:31.237Z - MT Broker returns from ReconcileKind
23T08:08:32.137Z - Done

Total time spend reconciling is listed as ~1.62s. We spend half a second before our code runs, we spend .2 seconds in our reconcilekind and then .9 seconds basically postprocessing.

.9 seconds includes the Update status => API call, so if we're indeed being throttled that very well could be what we're running up against here. .5 seconds before we even get to run our code is quite confusing. Only things I see there are stats being reported. Note this is just a deeper dig into a single reconcile that took a long time. I had also removed the Event generation from the reconciler (regarding the finalizerupdate event).

vaikas commented 4 years ago

One more... Just been playing with the traces more and for each Trigger created, we'll see the following (totally expected from the code). The only thing I'm curious is the two watches being set up from the looks of it. 

I0723 12:53:04.561980       1 round_trippers.go:420] POST https://10.12.0.1:443/apis/messaging.knative.dev/v1/namespaces/vaikas-test/subscriptions
I0723 12:53:04.586174       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status
I0723 12:53:04.956800       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status
I0723 12:53:05.068045       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status
I0723 12:53:05.169038       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status
I0723 12:53:21.329653       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/eventing.knative.dev/v1/triggers?allowWatchBookmarks=true&resourceVersion=20309359&timeout=7m20s&timeoutSeconds=440&watch=true
I0723 12:54:44.326166       1 round_trippers.go:420] GET https://10.12.0.1:443/apis/eventing.knative.dev/v1/brokers?allowWatchBookmarks=true&resourceVersion=20302382&timeout=6m27s&timeoutSeconds=387&watch=true
I0723 12:55:55.354859       1 round_trippers.go:420] POST https://10.12.0.1:443/apis/messaging.knative.dev/v1/namespaces/vaikas-test/subscriptions
I0723 12:55:55.377548       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status
I0723 12:55:55.531537       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status
I0723 12:55:55.621687       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status
I0723 12:55:55.723432       1 round_trippers.go:420] PUT https://10.12.0.1:443/apis/eventing.knative.dev/v1/namespaces/vaikas-test/triggers/trigger3/status