From 35a5d7db798cffb8e9dbc5d43db7c315111ee535 Mon Sep 17 00:00:00 2001 From: Matthias Rinck <56343232+rinckm@users.noreply.github.com> Date: Wed, 11 Jan 2023 14:50:45 +0100 Subject: [PATCH] Fix start time of phase "running" (#350) * fix get start time Co-authored-by: Andreas Brehmer <38314220+anbrsap@users.noreply.github.com> --- changelog.yaml | 14 +++++++ pkg/runctl/controller_test.go | 75 ++++++++++++++++++++++------------- pkg/runctl/run.go | 14 ++++++- pkg/runctl/run_test.go | 14 +++---- 4 files changed, 81 insertions(+), 36 deletions(-) diff --git a/changelog.yaml b/changelog.yaml index f0fbe0c3..146fd43a 100644 --- a/changelog.yaml +++ b/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: diff --git a/pkg/runctl/controller_test.go b/pkg/runctl/controller_test.go index 469ca92f..2458fb36 100644 --- a/pkg/runctl/controller_test.go +++ b/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) { diff --git a/pkg/runctl/run.go b/pkg/runctl/run.go index 532f9f99..fa657293 100644 --- a/pkg/runctl/run.go +++ b/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 diff --git a/pkg/runctl/run_test.go b/pkg/runctl/run_test.go index 20f7f1e7..49189c49 100644 --- a/pkg/runctl/run_test.go +++ b/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))