Fix start time of phase "running" (#350)

* fix get start time

Co-authored-by: Andreas Brehmer <[email protected]>

changelog.yaml

@@ -52,6 +52,20 @@
   date: TBD
   changes:
 
+    - type: internal
+      impact: patch
+      title: Fix start time of phase "running"
+      description: |-
+        The start time of phase "running" was set to the start time of the
+        Tekton TaskRun for JFR, which is when the pod has been _created_.
+        But phase "waiting" now covers the time until successful start-up
+        of the containers in the pod, which can be significantly after pod
+        creation, e.g. due to image pull time.
+        Therefore, the start time of phase "running" is now the start time
+        of the the JRF container.
+      pullRequestNumber: 350
+      jiraIssueNumber: 1974
+
 - version: "0.24.0"
   date: 2022-12-23
   changes:

pkg/runctl/controller_test.go

@@ -2,6 +2,7 @@ package runctl
 
 import (
 	"context"
+	"encoding/json"
 	"fmt"
 	"strings"
 	"testing"
@@ -90,37 +91,55 @@ func Test_Controller_Success(t *testing.T) {
 func Test_Controller_Running(t *testing.T) {
 	t.Parallel()
 
-	// SETUP
-	cf := newFakeClientFactory(
-		fake.SecretOpaque("secret1", "ns1"),
-		fake.ClusterRole(string(runClusterRoleName)),
-	)
-	pr := fake.PipelineRun("run1", "ns1", api.PipelineSpec{
-		Secrets: []string{"secret1"},
-	})
+	for _, containerState := range []string{
+		"running",
+		"terminated",
+	} {
+		t.Run(containerState, func(t *testing.T) {
+
+			// SETUP
+			cf := newFakeClientFactory(
+				fake.SecretOpaque("secret1", "ns1"),
+				fake.ClusterRole(string(runClusterRoleName)),
+			)
+			pr := fake.PipelineRun("run1", "ns1", api.PipelineSpec{
+				Secrets: []string{"secret1"},
+			})
 
-	// EXERCISE
-	stopCh := startController(t, cf)
-	defer stopController(t, stopCh)
-	createRun(t, pr, cf)
+			// EXERCISE
+			stopCh := startController(t, cf)
+			defer stopController(t, stopCh)
+			createRun(t, pr, cf)
+
+			// VERIFY
+			run := getPipelineRun(t, "run1", "ns1", cf)
+			runNs := run.GetRunNamespace()
+			taskRun := getTektonTaskRun(t, runNs, cf)
+			now := metav1.Now()
+			taskRun.Status.Steps = stepsWithContainer(containerState, now)
+			condition := apis.Condition{
+				Type:   apis.ConditionSucceeded,
+				Status: corev1.ConditionUnknown,
+				Reason: tekton.TaskRunReasonRunning.String(),
+			}
+			taskRun.Status.SetCondition(&condition)
+			updateTektonTaskRun(t, taskRun, runNs, cf)
+			cf.Sleep("Waiting for Tekton TaskRun being started")
+			run = getPipelineRun(t, "run1", "ns1", cf)
+			status := run.GetStatus()
+			assert.Equal(t, api.StateRunning, status.State)
+		})
+	}
+}
 
-	// VERIFY
-	run := getPipelineRun(t, "run1", "ns1", cf)
-	runNs := run.GetRunNamespace()
-	taskRun := getTektonTaskRun(t, runNs, cf)
-	now := metav1.Now()
-	taskRun.Status.StartTime = &now
-	condition := apis.Condition{
-		Type:   apis.ConditionSucceeded,
-		Status: corev1.ConditionUnknown,
-		Reason: tekton.TaskRunReasonRunning.String(),
+func stepsWithContainer(state string, startTime metav1.Time) []tekton.StepState {
+	var stepState tekton.StepState
+	time, _ := json.Marshal(startTime)
+	s := fmt.Sprintf(`{ %q: {"startedAt": %s}, "container": %q, "name": "foo"}`, state, time, jfrStepName)
+	json.Unmarshal([]byte(s), &stepState)
+	return []tekton.StepState{
+		stepState,
 	}
-	taskRun.Status.SetCondition(&condition)
-	updateTektonTaskRun(t, taskRun, runNs, cf)
-	cf.Sleep("Waiting for Tekton TaskRun being started")
-	run = getPipelineRun(t, "run1", "ns1", cf)
-	status := run.GetStatus()
-	assert.Equal(t, api.StateRunning, status.State)
 }
 
 func Test_Controller_Deletion(t *testing.T) {

pkg/runctl/run.go

@@ -11,6 +11,10 @@ import (
 	knativeapis "knative.dev/pkg/apis"
 )
 
+const (
+	jfrStepName = "step-jenkinsfile-runner"
+)
+
 type tektonRun struct {
 	tektonTaskRun *tekton.TaskRun
 }
@@ -30,7 +34,15 @@ func (r *tektonRun) GetStartTime() *metav1.Time {
 	if condition.IsUnknown() && condition.Reason != tekton.TaskRunReasonRunning.String() {
 		return nil
 	}
-	return r.tektonTaskRun.Status.StartTime
+	for _, step := range r.tektonTaskRun.Status.Steps {
+		if step.ContainerName == jfrStepName && step.Running != nil {
+			return &step.Running.StartedAt
+		}
+		if step.ContainerName == jfrStepName && step.Terminated != nil {
+			return &step.Terminated.StartedAt
+		}
+	}
+	return nil
 }
 
 // GetCompletionTime returns completion time of run if already completed

pkg/runctl/run_test.go

@@ -14,10 +14,10 @@ import (
 )
 
 const (
-	time1                     = `2019-05-14T08:24:08Z`
+	taskStartTime             = `2019-05-14T08:24:08Z`
+	stepStartTime             = `2019-05-14T08:24:11Z`
 	emptyBuild                = `{}`
-	startedBuild              = `{"status": {"startTime": "` + time1 + `"}}`
-	runningBuild              = `{"status": {"steps": [{"name": "jenkinsfile-runner", "running": {"startedAt": "` + time1 + `"}}]}}`
+	runningBuild              = `{"status": {"steps": [{"name": "jenkinsfile-runner", "running": {"startedAt": "` + stepStartTime + `"}}]}}`
 	completedSuccess          = `{"status": {"conditions": [{"message": "message1", "reason": "Succeeded", "status": "True", "type": "Succeeded"}], "steps": [{"name": "jenkinsfile-runner", "terminated": {"reason": "Completed", "message": "ok", "exitCode": 0}}]}}`
 	completedFail             = `{"status": {"conditions": [{"message": "message1", "reason": "Failed", "status": "False", "type": "Succeeded"}], "steps": [{"name": "jenkinsfile-runner", "terminated": {"reason": "Error", "message": "ko", "exitCode": 1}}]}}`
 	completedValidationFailed = `{"status": {"conditions": [{"message": "message1", "reason": "TaskRunValidationFailed", "status": "False", "type": "Succeeded"}]}}`
@@ -26,19 +26,19 @@ const (
 
 	realStartedBuild = `status:
   conditions:
-  - lastTransitionTime: "2019-05-14T08:24:12Z"
+  - lastTransitionTime: ` + taskStartTime + `
     message: Not all Steps in the Task have finished executing
     reason: Running
     status: Unknown
     type: Succeeded
   podName: build-pod-38aa76
-  startTime: "` + time1 + `"
+  startTime: 
   steps:
   - container: step-jenkinsfile-runner
     imageID: docker-pullable://alpine@sha256:acd3ca9941a85e8ed16515bfc5328e4e2f8c128caa72959a58a127b7801ee01f
     name: jenkinsfile-runner
     running:
-      startedAt: "2019-05-14T08:24:11Z"
+      startedAt: "` + stepStartTime + `"
 `
 
 	realCompletedSuccess = `status:
@@ -148,7 +148,7 @@ func Test__GetStartTime_UnsetReturnsNil(t *testing.T) {
 }
 
 func Test__GetStartTime_Set(t *testing.T) {
-	expectedTime := generateTime(time1)
+	expectedTime := generateTime(stepStartTime)
 	run := NewRun(fakeTektonTaskRunYaml(realStartedBuild))
 	startTime := run.GetStartTime()
 	assert.Assert(t, expectedTime.Equal(startTime), fmt.Sprintf("Expected: %s, Is: %s", expectedTime, startTime))