fix: the pr may lose finallyStartTime when pipeline controller is not…

… synchronized to all current state

pkg/reconciler/pipelinerun/pipelinerun.go

@@ -799,6 +799,12 @@ func (c *Reconciler) runNextSchedulableTask(ctx context.Context, pr *v1.Pipeline
 		}
 	}
 
+	// If FinallyStartTime is not set, and one or more final tasks has been created
+	// Try to set the FinallyStartTime of this PipelineRun
+	if pr.Status.FinallyStartTime == nil && pipelineRunFacts.IsFinalTaskStarted() {
+		c.setFinallyStartedTimeIfNeeded(pr, pipelineRunFacts)
+	}
+
 	for _, rpt := range nextRpts {
 		if rpt.IsFinalTask(pipelineRunFacts) {
 			c.setFinallyStartedTimeIfNeeded(pr, pipelineRunFacts)

pkg/reconciler/pipelinerun/pipelinerun_test.go

@@ -2827,6 +2827,257 @@ status:
 	}
 }
 
+func TestReconcileWithFinallyStartTime(t *testing.T) {
+	// TestReconcileWithFinallyStartTime runs "Reconcile" on a PipelineRun with tasks is completed and one or more finally tasks
+	// may need to be executed.
+	// It verifies that reconcile is successful, the finallyStartTime can be set correctly.
+	pipelineFinalTask := parse.MustParseV1Pipeline(t, `
+metadata:
+  name: test-pipeline-with-finally
+  namespace: foo
+spec:
+  finally:
+  - name: finaltask-1
+    taskRef:
+      name: hello-world
+  tasks:
+  - name: task1
+    taskRef:
+      name: hello-world
+`)
+	pipelineNotFinalTask := parse.MustParseV1Pipeline(t, `
+metadata:
+  name: test-pipeline-with-finally
+  namespace: foo
+spec:
+  tasks:
+  - name: task1
+    taskRef:
+      name: hello-world
+`)
+	pipelineSkippedFinalTask := parse.MustParseV1Pipeline(t, `
+metadata:
+  name: test-pipeline-with-finally
+  namespace: foo
+spec:
+  finally:
+  - name: finaltask-1
+    when:
+    - input: "$(tasks.task1.status)"
+      operator: in
+      values: ["Failure"]
+    taskRef:
+      name: hello-world
+  tasks:
+  - name: task1
+    taskRef:
+      name: hello-world
+`)
+
+	prName := "test-pipeline-run-with-set-finally-start-time"
+	ts := []*v1.Task{simpleHelloWorldTask}
+
+	tcs := []struct {
+		name                 string
+		trs                  []*v1.TaskRun
+		ps                   []*v1.Pipeline
+		pr                   *v1.PipelineRun
+		wantEvents           []string
+		wantFinallyStartTime bool
+	}{{
+		name: "new final task created",
+		trs: []*v1.TaskRun{
+			getTaskRun(
+				t,
+				"test-pipeline-run-with-set-finally-start-time-hello-world",
+				prName,
+				"test-pipeline-with-finally",
+				"hello-world",
+				corev1.ConditionTrue,
+			),
+		},
+		ps: []*v1.Pipeline{pipelineFinalTask},
+		pr: parse.MustParseV1PipelineRun(t, fmt.Sprintf(`
+metadata:
+  name: %s
+  namespace: foo
+spec:
+  pipelineRef:
+    name: test-pipeline-with-finally
+status:
+  startTime: "2021-12-31T23:40:00Z"
+  childReferences:
+  - name: test-pipeline-run-with-set-finally-start-time-hello-world
+    apiVersion: tekton.dev/v1
+    kind: TaskRun
+    pipelineTaskName: task1
+    status:
+      conditions:
+      - lastTransitionTime: null
+        status: "True"
+        type: Succeeded
+`, prName)),
+		wantEvents: []string{
+			"Normal Started",
+		},
+		wantFinallyStartTime: true,
+	}, {
+		name: "final task started and the pr not final start time",
+		trs: []*v1.TaskRun{
+			getTaskRun(
+				t,
+				"test-pipeline-run-with-set-finally-start-time-hello-world",
+				prName,
+				"test-pipeline-with-finally",
+				"hello-world",
+				corev1.ConditionTrue,
+			),
+			mustParseTaskRunWithObjectMeta(t, taskRunObjectMeta("test-pipeline-run-with-finally-start-time-finaltask-1", "foo", prName,
+				"test-pipeline-with-finally", "finaltask-1", false), `
+spec:
+  serviceAccountName: test-sa
+  taskRef:
+    name: hello-world
+    kind: Task
+`)},
+		ps: []*v1.Pipeline{pipelineFinalTask},
+		pr: parse.MustParseV1PipelineRun(t, fmt.Sprintf(`
+metadata:
+  name: %s
+  namespace: foo
+spec:
+  pipelineRef:
+    name: test-pipeline-with-finally
+  timeouts:
+    tasks: 5m
+    pipeline: 20m
+status:
+  startTime: "2021-12-31T23:40:00Z"
+  childReferences:
+  - name: test-pipeline-run-with-set-finally-start-time-hello-world
+    apiVersion: tekton.dev/v1
+    kind: TaskRun
+    pipelineTaskName: task1
+    status:
+      conditions:
+      - lastTransitionTime: null
+        status: "True"
+        type: Succeeded
+  - name: test-pipeline-run-with-set-finally-start-time-finaltask-1
+    apiVersion: tekton.dev/v1
+    kind: TaskRun
+    pipelineTaskName: finaltask-1
+    status:
+      conditions:
+      - lastTransitionTime: null
+        status: "Unknown"
+        type: Succeeded
+`, prName)),
+		wantEvents: []string{
+			"Normal Started",
+		},
+		wantFinallyStartTime: true,
+	}, {
+		name: "final task not exist",
+		trs: []*v1.TaskRun{
+			getTaskRun(
+				t,
+				"test-pipeline-run-with-set-finally-start-time-hello-world",
+				prName,
+				"test-pipeline-with-finally",
+				"hello-world",
+				corev1.ConditionTrue,
+			),
+		},
+		ps: []*v1.Pipeline{pipelineNotFinalTask},
+		pr: parse.MustParseV1PipelineRun(t, fmt.Sprintf(`
+metadata:
+  name: %s
+  namespace: foo
+spec:
+  pipelineRef:
+    name: test-pipeline-with-finally
+  timeouts:
+    tasks: 5m
+    pipeline: 20m
+status:
+  startTime: "2021-12-31T23:40:00Z"
+  childReferences:
+  - name: test-pipeline-run-with-set-finally-start-time-hello-world
+    apiVersion: tekton.dev/v1
+    kind: TaskRun
+    pipelineTaskName: task1
+    status:
+      conditions:
+      - lastTransitionTime: null
+        status: "True"
+        type: Succeeded
+`, prName)),
+		wantEvents: []string{
+			"Normal Succeeded Tasks Completed: 1 (Failed: 0, Cancelled 0), Skipped: 0",
+		},
+		wantFinallyStartTime: false,
+	}, {
+		name: "final task skipped",
+		trs: []*v1.TaskRun{
+			getTaskRun(
+				t,
+				"test-pipeline-run-with-set-finally-start-time-hello-world",
+				prName,
+				"test-pipeline-with-finally",
+				"hello-world",
+				corev1.ConditionTrue,
+			),
+		},
+		ps: []*v1.Pipeline{pipelineSkippedFinalTask},
+		pr: parse.MustParseV1PipelineRun(t, fmt.Sprintf(`
+metadata:
+  name: %s
+  namespace: foo
+spec:
+  pipelineRef:
+    name: test-pipeline-with-finally
+  timeouts:
+    tasks: 5m
+    pipeline: 20m
+status:
+  startTime: "2021-12-31T23:40:00Z"
+  childReferences:
+  - name: test-pipeline-run-with-set-finally-start-time-hello-world
+    apiVersion: tekton.dev/v1
+    kind: TaskRun
+    pipelineTaskName: task1
+    status:
+      conditions:
+      - lastTransitionTime: null
+        status: "True"
+        type: Succeeded
+`, prName)),
+		wantEvents: []string{
+			"Normal Succeeded Tasks Completed: 1 (Failed: 0, Cancelled 0), Skipped: 1",
+		},
+		wantFinallyStartTime: true,
+	}}
+	for _, tc := range tcs {
+		withOwnerReference(tc.trs, prName)
+
+		d := test.Data{
+			PipelineRuns: []*v1.PipelineRun{tc.pr},
+			Pipelines:    tc.ps,
+			Tasks:        ts,
+			TaskRuns:     tc.trs,
+		}
+		prt := newPipelineRunTest(t, d)
+		defer prt.Cancel()
+
+		reconciledRun, _ := prt.reconcileRun("foo", prName, tc.wantEvents, false)
+
+		if tc.wantFinallyStartTime != (reconciledRun.Status.FinallyStartTime != nil) {
+			t.Errorf("Expected FinallyStartTime != nil to be %t, but was %t", tc.wantFinallyStartTime, reconciledRun.Status.FinallyStartTime != nil)
+		}
+	}
+}
+
 func TestReconcileWithoutPVC(t *testing.T) {
 	// TestReconcileWithoutPVC runs "Reconcile" on a PipelineRun that has two unrelated tasks.
 	// It verifies that reconcile is successful and that no PVC is created
@@ -4812,7 +5063,7 @@ status:
 	expectedPr := expectedPrStatus
 
 	if d := cmp.Diff(expectedPr, reconciledRun, ignoreResourceVersion, ignoreLastTransitionTime, ignoreCompletionTime, ignoreStartTime,
-		ignoreProvenance, cmpopts.EquateEmpty()); d != "" {
+		ignoreProvenance, ignoreFinallyStartTime, cmpopts.EquateEmpty()); d != "" {
 		t.Errorf("expected to see pipeline run results created. Diff %s", diff.PrintWantGot(d))
 	}
 }

pkg/reconciler/pipelinerun/resources/pipelinerunstate.go

@@ -358,6 +358,24 @@ func (facts *PipelineRunFacts) GetFinalTasks() PipelineRunState {
 	return tasks
 }
 
+// IsFinalTaskStarted returns true if all DAG pipelineTasks is finished and one or more final tasks have been created.
+func (facts *PipelineRunFacts) IsFinalTaskStarted() bool {
+	// check either pipeline has finished executing all DAG pipelineTasks,
+	// where "finished executing" means succeeded, failed, or skipped.
+	if facts.checkDAGTasksDone() {
+		// return list of tasks with all final tasks
+		for _, t := range facts.State {
+			if facts.isFinalTask(t.PipelineTask.Name) {
+				if len(t.TaskRuns) > 0 || len(t.CustomRuns) > 0 {
+					return true
+				}
+			}
+		}
+	}
+
+	return false
+}
+
 // GetPipelineConditionStatus will return the Condition that the PipelineRun prName should be
 // updated with, based on the status of the TaskRuns in state.
 func (facts *PipelineRunFacts) GetPipelineConditionStatus(ctx context.Context, pr *v1.PipelineRun, logger *zap.SugaredLogger, c clock.PassiveClock) *apis.Condition {

pkg/reconciler/pipelinerun/resources/pipelinerunstate_test.go

@@ -1545,6 +1545,77 @@ func TestPipelineRunState_GetFinalTasksAndNames(t *testing.T) {
 	}
 }
 
+func TestPipelineRunState_IsFinalTaskStarted(t *testing.T) {
+	tcs := []struct {
+		name                     string
+		desc                     string
+		state                    PipelineRunState
+		DAGTasks                 []v1.PipelineTask
+		finalTasks               []v1.PipelineTask
+		expectedFinalTaskStarted bool
+	}{{
+		// tasks: [ mytask1(started)]
+		// finally: [mytask2(not created)]
+		name:                     "01 - DAG task started, final task not created",
+		desc:                     "DAG tasks (mytask1) started yet - do not schedule final tasks (mytask2)",
+		state:                    oneStartedState,
+		DAGTasks:                 []v1.PipelineTask{pts[0]},
+		finalTasks:               []v1.PipelineTask{pts[1]},
+		expectedFinalTaskStarted: false,
+	}, {
+		// tasks: [ mytask1(done)]
+		// finally: [mytask2(not created)]
+		name:                     "02 - DAG task succeeded, final task not created",
+		desc:                     "DAG tasks (mytask1) finished successfully - do not schedule final tasks (mytask2)",
+		state:                    oneFinishedState,
+		DAGTasks:                 []v1.PipelineTask{pts[0]},
+		finalTasks:               []v1.PipelineTask{pts[1]},
+		expectedFinalTaskStarted: false,
+	}, {
+		// tasks: [ mytask1(done)]
+		// none finally
+		name:                     "03 - DAG task succeeded, no final tasks",
+		desc:                     "DAG tasks (mytask1) finished successfully - no final tasks",
+		state:                    oneStartedState,
+		DAGTasks:                 []v1.PipelineTask{pts[0]},
+		finalTasks:               []v1.PipelineTask{},
+		expectedFinalTaskStarted: false,
+	}, {
+		// tasks: [ mytask1(done)]
+		// finally: [mytask2(done)]
+		name:                     "04 - DAG task succeeded, final tasks (mytask2) succeeded",
+		desc:                     "DAG tasks (mytask1) finished successfully - final tasks (mytask2) finished successfully",
+		state:                    allFinishedState,
+		DAGTasks:                 []v1.PipelineTask{pts[0]},
+		finalTasks:               []v1.PipelineTask{pts[1]},
+		expectedFinalTaskStarted: true,
+	}}
+	for _, tc := range tcs {
+		dagGraph, err := dag.Build(v1.PipelineTaskList(tc.DAGTasks), v1.PipelineTaskList(tc.DAGTasks).Deps())
+		if err != nil {
+			t.Fatalf("Unexpected error while building DAG for pipelineTasks %v: %v", tc.DAGTasks, err)
+		}
+		finalGraph, err := dag.Build(v1.PipelineTaskList(tc.finalTasks), map[string][]string{})
+		if err != nil {
+			t.Fatalf("Unexpected error while building DAG for final pipelineTasks %v: %v", tc.finalTasks, err)
+		}
+		t.Run(tc.name, func(t *testing.T) {
+			facts := PipelineRunFacts{
+				State:           tc.state,
+				TasksGraph:      dagGraph,
+				FinalTasksGraph: finalGraph,
+				TimeoutsState: PipelineRunTimeoutsState{
+					Clock: testClock,
+				},
+			}
+			started := facts.IsFinalTaskStarted()
+			if d := cmp.Diff(tc.expectedFinalTaskStarted, started); d != "" {
+				t.Errorf("Didn't get expected (IsFinalTaskStarted) started for %s (%s):%s", tc.name, tc.desc, diff.PrintWantGot(d))
+			}
+		})
+	}
+}
+
 func TestGetPipelineConditionStatus(t *testing.T) {
 	var taskRetriedState = PipelineRunState{{
 		PipelineTask: &pts[3], // 1 retry needed