[recordevents] Removed EventBroadcaster usage and replaced with manual send

[slinkydeveloper]

Signed-off-by: Francesco Guardiani francescoguard@gmail.com

Proposed Changes

• tl;dr Removed EventBroadcaster usage because it manually creates the event and, in some particular conditions of high load, it generates 2 events with the same name
• Reintroduced logger vent to properly log the events
• Not sending ce- headers anymore in EventInfo.HTTPHeaders (they're just polluting event info)

More info

So we noticed this issue both in openshift CI and mink CI. The problem is that, when the system is under high load, the time syscall might return the same value if 2 calls are made "at the same time". Because EventBroadcaster uses the time to name the events, two events might have the same name, and obviously the kube api-server rejects one of them. With this change, we use the pod name + sequence number, which are guaranteed to be unique in the same pod.

{"level":"info","ts":1603732389.152021,"logger":"fallback","caller":"recorder_vent/constructor.go:142","msg":"Server rejected event '&v1.Event{TypeMeta:v1.TypeMeta{Kind:\"\", APIVersion:\"\"}, ObjectMeta:v1.ObjectMeta{Name:\"e2e-channelchain-recordevents-pod.16419a1c68eb2169\", GenerateName:\"\", Namespace:\"test-channel-chain-v1beta1-in-memory-channel-messaging-knadj9q2\", SelfLink:\"\", UID:\"\", ResourceVersion:\"\", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Finalizers:[]string(nil), ClusterName:\"\", ManagedFields:[]v1.ManagedFieldsEntry(nil)}, InvolvedObject:v1.ObjectReference{Kind:\"Pod\", Namespace:\"test-channel-chain-v1beta1-in-memory-channel-messaging-knadj9q2\", Name:\"e2e-channelchain-recordevents-pod\", UID:\"7ca9da82-6f01-4722-80eb-7ce7a8c1be7a\", APIVersion:\"v1\", ResourceVersion:\"238536\", FieldPath:\"\"}, Reason:\"CloudEventObserved\", Message:\"{\\\"event\\\":{\\\"data\\\":{\\\"msg\\\":\\\"TestSingleEvent 9f473905-a8cd-47f5-a480-e9189838da54\\\"},\\\"datacontenttype\\\":\\\"application/json\\\",\\\"id\\\":\\\"dummy\\\",\\\"knativehistory\\\":\\\"e2e-channelchain1-kn-channel.test-channel-chain-v1beta1-in-memory-channel-messaging-knadj9q2.svc.cluster.local; e2e-channelchain2-kn-channel.test-channel-chain-v1beta1-in-memory-channel-messaging-knadj9q2.svc.cluster.local\\\",\\\"source\\\":\\\"http://e2e-channelchain-sender.svc/\\\",\\\"specversion\\\":\\\"1.0\\\",\\\"type\\\":\\\"dev.knative.test.event\\\"},\\\"httpHeaders\\\":{\\\"Accept-Encoding\\\":[\\\"gzip\\\"],\\\"Ce-Id\\\":[\\\"dummy\\\"],\\\"Ce-Knativehistory\\\":[\\\"e2e-channelchain1-kn-channel.test-channel-chain-v1beta1-in-memory-channel-messaging-knadj9q2.svc.cluster.local; e2e-channelchain2-kn-channel.test-channel-chain-v1beta1-in-memory-channel-messaging-knadj9q2.svc.cluster.local\\\"],\\\"Ce-Source\\\":[\\\"http://e2e-channelchain-sender.svc/\\\"],\\\"Ce-Specversion\\\":[\\\"1.0\\\"],\\\"Ce-Type\\\":[\\\"dev.knative.test.event\\\"],\\\"Content-Length\\\":[\\\"62\\\"],\\\"Content-Type\\\":[\\\"application/json\\\"],\\\"Traceparent\\\":[\\\"00-92dd54cca062bf624beac79e0950d569-061dd257c4fa8d00-01\\\"],\\\"User-Agent\\\":[\\\"Go-http-client/1.1\\\"]},\\\"origin\\\":\\\"10.131.2.12:42716\\\",\\\"observer\\\":\\\"observer-default\\\",\\\"time\\\":\\\"2020-10-26T17:13:09.130037875Z\\\",\\\"sequence\\\":1}\", Source:v1.EventSource{Component:\"observer-default\", Host:\"\"}, FirstTimestamp:v1.Time{Time:time.Time{wall:0xbfdddec947c8ef69, ext:36416683230, loc:(*time.Location)(0x2d19060)}}, LastTimestamp:v1.Time{Time:time.Time{wall:0xbfdddec947c8ef69, ext:36416683230, loc:(*time.Location)(0x2d19060)}}, Count:1, Type:\"Normal\", EventTime:v1.MicroTime{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, Series:(*v1.EventSeries)(nil), Action:\"\", Related:(*v1.ObjectReference)(nil), ReportingController:\"\", ReportingInstance:\"\"}': 'events \"e2e-channelchain-recordevents-pod.16419a1c68eb2169\" already exists' (will not retry!)"}

[codecov]

Codecov Report

Merging #4393 into master will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff           @@
##           master    #4393   +/-   ##
=======================================
  Coverage   81.06%   81.06%           
=======================================
  Files         281      281           
  Lines        7964     7964           
=======================================
  Hits         6456     6456           
  Misses       1122     1122           
  Partials      386      386           

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 0a54fd9...e67ec1e. Read the comment docs.

[slinkydeveloper]

{"level":"error","ts":1603742071.5605693,"logger":"fallback","caller":"recorder_vent/recorder.go:110","msg":"Server rejected event 'e2e-brokerchannel-logger-pod2.1': 'Event \"e2e-brokerchannel-logger-pod2.1\" is invalid: [reportingController: Required value, reportingController: Invalid value: \"\": name part must be non-empty, reportingController: Invalid value: \"\": name part must consist of alphanumeric characters, '-', '_' or '.', and must start and end with an alphanumeric character (e.g. 'MyName',  or 'my.name',  or '123-abc', regex used for validation is '([A-Za-z0-9][-A-Za-z0-9_.]*)?[A-Za-z0-9]'), reportingInstance: Required value, action: Required value, message: Invalid value: \"\": can have at most 1024 characters]' (will not retry!)","stacktrace":"knative.dev/eventing/test/lib/recordevents/recorder_vent.(*recorder).trySendEvent\n\tknative.dev/eventing/test/lib/recordevents/recorder_vent/recorder.go:110\nknative.dev/eventing/test/lib/recordevents/recorder_vent.(*recorder).recordEvent\n\tknative.dev/eventing/test/lib/recordevents/recorder_vent/recorder.go:73\nknative.dev/eventing/test/lib/recordevents/recorder_vent.(*recorder).Vent\n\tknative.dev/eventing/test/lib/recordevents/recorder_vent/recorder.go:67\nknative.dev/eventing/test/lib/recordevents.EventLogs.Vent\n\tknative.dev/eventing/test/lib/recordevents/event_log.go:28\nknative.dev/eventing/test/lib/recordevents/observer.(*Observer).ServeHTTP\n\tknative.dev/eventing/test/lib/recordevents/observer/observer.go:141\ngo.opencensus.io/plugin/ochttp.(*Handler).ServeHTTP\n\tgo.opencensus.io@v0.22.4/plugin/ochttp/server.go:92\nnet/http.serverHandler.ServeHTTP\n\tnet/http/server.go:2836\nnet/http.(*conn).serve\n\tnet/http/server.go:1924"}

Looking at it, but that's weird. Reporting controller is an optional value

[vaikas]

/lgtm
/approve

[slinkydeveloper]

Funky, hit the time limit even if all asserts passed?!

/retest

[slinkydeveloper]

Server rejected event 'e2e-api-server-source-logger-pod-event-ref-match-label-expr.1'. Reason: 'Event "e2e-api-server-source-logger-pod-event-ref-match-label-expr.1" is invalid: message: Invalid value: "": can have at most 1024 characters' (will not retry!)

But this didn't come out before this pr!

[matzew]

/lgtm

[slinkydeveloper]

@lionelvillard there aren't any quotas, it's a bug/weird behaviour of k8s: kubernetes/kubernetes#95913

[vaikas]

/lgtm
/approve

[lionelvillard]

@slinkydeveloper how the validation bug/underspecification related to the API server rate limit?

[slinkydeveloper]

which API server rate limit? I'm lost 😄

[lionelvillard]

https://kubernetes.io/docs/concepts/cluster-administration/flow-control/

It might not be an issue, but this is something to be aware of.

[slinkydeveloper]

Ah well, we use this method to propagate events already since a bunch of weeks and we still didn't hit that issue. This PR is about fixing some disambiguation issue the EventBroadcaster generates

[slinkydeveloper]

/retest

[vaikas]

/lgtm
/approve

[knative-prow-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: slinkydeveloper, vaikas

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details

Needs approval from an approver in each of these files:

• test/OWNERS [slinkydeveloper,vaikas]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment