Pipelinerun controller creates duplicate events

[GregDritschler]

Expected Behavior

When an event occurs a single time, the event count is 1.

Actual Behavior

The event count is 2.

We have e2e tests that verify event counts. This bug causes them to fail. Here is one example:

https://tekton-releases.appspot.com/build/tekton-prow/pr-logs/pull/tektoncd_pipeline/2850/pull-tekton-pipeline-integration-tests/1275691939903049728/

    TestPipelineRun/pipeline_succeeds_when_task_skipped_due_to_failed_condition: pipelinerun_test.go:214: Expected 1 number of successful events from pipelinerun and taskrun but got 2; list of receieved events : "&v1.Event{TypeMeta:v1.TypeMeta{Kind:\"\", APIVersion:\"\"}, ObjectMeta:v1.ObjectMeta{Name:\"pipelinerun2.161b6ac6ae32bdbe\", GenerateName:\"\", Namespace:\"arendelle-2hhc6\", SelfLink:\"/api/v1/namespaces/arendelle-2hhc6/events/pipelinerun2.161b6ac6ae32bdbe\", UID:\"b0eb6536-beb7-4e47-bd41-1dc33675eaca\", ResourceVersion:\"2255\", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63728581095, loc:(*time.Location)(0x39d65e0)}}, 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:\"PipelineRun\", Namespace:\"arendelle-2hhc6\", Name:\"pipelinerun2\", UID:\"3afc45c6-2e3f-4736-b1ee-6cc0af5feed4\", APIVersion:\"tekton.dev/v1beta1\", ResourceVersion:\"5184\", FieldPath:\"\"}, Reason:\"Succeeded\", Message:\"Tasks Completed: 0 (Failed: 0, Cancelled 0), Skipped: 2\", Source:v1.EventSource{Component:\"PipelineRun\", Host:\"\"}, FirstTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63728581094, loc:(*time.Location)(0x39d65e0)}}, LastTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63728581094, loc:(*time.Location)(0x39d65e0)}}, 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:\"\"}, &v1.Event{TypeMeta:v1.TypeMeta{Kind:\"\", APIVersion:\"\"}, ObjectMeta:v1.ObjectMeta{Name:\"pipelinerun2.161b6ac6ae32bdbe\", GenerateName:\"\", Namespace:\"arendelle-2hhc6\", SelfLink:\"/api/v1/namespaces/arendelle-2hhc6/events/pipelinerun2.161b6ac6ae32bdbe\", UID:\"b0eb6536-beb7-4e47-bd41-1dc33675eaca\", ResourceVersion:\"2256\", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63728581095, loc:(*time.Location)(0x39d65e0)}}, 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:\"PipelineRun\", Namespace:\"arendelle-2hhc6\", Name:\"pipelinerun2\", UID:\"3afc45c6-2e3f-4736-b1ee-6cc0af5feed4\", APIVersion:\"tekton.dev/v1beta1\", ResourceVersion:\"5184\", FieldPath:\"\"}, Reason:\"Succeeded\", Message:\"Tasks Completed: 0 (Failed: 0, Cancelled 0), Skipped: 2\", Source:v1.EventSource{Component:\"PipelineRun\", Host:\"\"}, FirstTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63728581094, loc:(*time.Location)(0x39d65e0)}}, LastTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:63728581094, loc:(*time.Location)(0x39d65e0)}}, Count:2, 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:\"\"}"

Steps to Reproduce the Problem

The problem can be seen with any PipelineRun but it is intermittent (perhaps because the event broadcaster is catching the duplicate?).

Additional Info

There are 2 calls to events.Emit, one at the end of the inner reconcile function (line 455) and another at the end of the outer reconcile function (line 210). This produces the same event twice. This bug may have been introduced in PR #2805.

• Kubernetes version: 1.16

• Tekton Pipeline version: Unreleased (master)

[vdemeester]

/kind bug
/kind flake
/area testing

/cc @afrittoli

[afrittoli]

Because the time stamps are identical, my impression is that something goes wrong in the fake recorder. I don't see how the controller could send the event twice with the same timestamps otherwise.

I've started looking into this, I'll try to see if this is something we can address in the test code.

[afrittoli]

Because the time stamps are identical, my impression is that something goes wrong in the fake recorder. I don't see how the controller could send the event twice with the same timestamps otherwise.

I've started looking into this, I'll try to see if this is something we can address in the test code.

never mind, I didn't read the issue properly - thank you for catching this!