Step finished runtime (#871)

* Add totoal runtime propoerty to step finished events * Remove unused runIf input from registerStepRunResults * Update tracker tests * Rename totalRuntime to runtime
bitrise-io · Jun 19, 2023 · 3686ace · 3686ace
1 parent 23a1e7c
commit 3686ace
Show file tree

Hide file tree

Showing 4 changed files with 36 additions and 23 deletions.
diff --git a/analytics/tracker.go b/analytics/tracker.go
@@ -53,6 +53,7 @@ const (
 	stepSourceProperty            = "step_source"
 	skippableProperty             = "skippable"
 	timeoutProperty               = "timeout"
+	runtime                       = "runtime"
 
 	failedValue          = "failed"
 	successfulValue      = "successful"
@@ -91,6 +92,7 @@ type StepResult struct {
 	Status                   models.StepRunStatus
 	ErrorMessage             string
 	Timeout, NoOutputTimeout time.Duration
+	Runtime                  time.Duration
 }
 
 // Tracker ...
@@ -308,5 +310,7 @@ func mapStepResultToEvent(result StepResult) (string, analytics.Properties, erro
 		return "", analytics.Properties{}, fmt.Errorf("Unknown step status code: %d", result.Status)
 	}
 
+	extraProperties[runtime] = int64(result.Runtime.Seconds())
+
 	return eventName, extraProperties, nil
 }
diff --git a/analytics/tracker_test.go b/analytics/tracker_test.go
@@ -19,10 +19,11 @@ func Test_mapStepResultToEvent(t *testing.T) {
 		{
 			name: "Step succeeded",
 			result: StepResult{
-				Status: models.StepRunStatusCodeSuccess,
+				Status:  models.StepRunStatusCodeSuccess,
+				Runtime: 30 * time.Second,
 			},
 			expectedEvent:      "step_finished",
-			expectedExtraProps: analytics.Properties{"status": "successful"},
+			expectedExtraProps: analytics.Properties{"status": "successful", "runtime": int64(30)},
 		},
 		{
 			name: "Step failed",
@@ -34,6 +35,7 @@ func Test_mapStepResultToEvent(t *testing.T) {
 			expectedExtraProps: analytics.Properties{
 				"status":        "failed",
 				"error_message": "msg",
+				"runtime":       int64(0),
 			},
 		},
 		{
@@ -42,7 +44,7 @@ func Test_mapStepResultToEvent(t *testing.T) {
 				Status: models.StepRunStatusCodeFailedSkippable,
 			},
 			expectedEvent:      "step_finished",
-			expectedExtraProps: analytics.Properties{"status": "failed"},
+			expectedExtraProps: analytics.Properties{"status": "failed", "runtime": int64(0)},
 		},
 		{
 			name: "Step skipped",
@@ -58,6 +60,7 @@ func Test_mapStepResultToEvent(t *testing.T) {
 				"reason":    "build_failed",
 				"skippable": true,
 				"step_id":   "ID",
+				"runtime":   int64(0),
 			},
 		},
 		{
@@ -69,6 +72,7 @@ func Test_mapStepResultToEvent(t *testing.T) {
 			expectedExtraProps: analytics.Properties{
 				"reason":    "run_if",
 				"skippable": false,
+				"runtime":   int64(0),
 			},
 		},
 		{
@@ -81,6 +85,7 @@ func Test_mapStepResultToEvent(t *testing.T) {
 			expectedExtraProps: analytics.Properties{
 				"skippable":     false,
 				"error_message": "msg",
+				"runtime":       int64(0),
 			},
 		},
 		{
@@ -93,6 +98,7 @@ func Test_mapStepResultToEvent(t *testing.T) {
 			expectedExtraProps: analytics.Properties{
 				"reason":  "timeout",
 				"timeout": int64(1),
+				"runtime": int64(0),
 			},
 		},
 		{
@@ -105,6 +111,7 @@ func Test_mapStepResultToEvent(t *testing.T) {
 			expectedExtraProps: analytics.Properties{
 				"reason":  "no_output_timeout",
 				"timeout": int64(1),
+				"runtime": int64(0),
 			},
 		},
 	}

diff --git a/cli/build_run_result_collector.go b/cli/build_run_result_collector.go
@@ -31,7 +31,6 @@ func (r buildRunResultCollector) registerStepRunResults(
 	step stepmanModels.StepModel,
 	stepInfoPtr stepmanModels.StepInfoModel,
 	stepIdxPtr int,
-	runIf string,
 	status models.StepRunStatus,
 	exitCode int,
 	err error,
@@ -40,6 +39,8 @@ func (r buildRunResultCollector) registerStepRunResults(
 	redactedStepInputs map[string]string,
 	properties coreanalytics.Properties) {
 
+	stepRuntime := time.Since(stepStartTime)
+
 	timeout, noOutputTimeout := time.Duration(-1), time.Duration(-1)
 	if status == models.StepRunStatusCodeFailed {
 		// Forward the status of a Step or a wrapped bitrise process.
@@ -93,7 +94,7 @@ func (r buildRunResultCollector) registerStepRunResults(
 		StepInputs: redactedStepInputs,
 		Status:     status,
 		Idx:        buildRunResults.ResultsCount(),
-		RunTime:    time.Since(stepStartTime),
+		RunTime:    stepRuntime,
 		ErrorStr:   errStr,
 		ExitCode:   exitCode,
 		StartTime:  stepStartTime,
@@ -108,6 +109,7 @@ func (r buildRunResultCollector) registerStepRunResults(
 		ErrorMessage:    errStr,
 		Timeout:         timeout,
 		NoOutputTimeout: noOutputTimeout,
+		Runtime:         stepRuntime,
 	})
 
 	switch status {

diff --git a/cli/run_util.go b/cli/run_util.go
@@ -618,29 +618,29 @@ func (r WorkflowRunner) activateAndRunSteps(
 
 		if err := bitrise.CleanupStepWorkDir(); err != nil {
 			runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-				"", models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
+				models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
 			continue
 		}
 
 		//
 		// Preparing the step
 		if err := tools.EnvmanInit(configs.InputEnvstorePath, true); err != nil {
 			runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-				"", models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
+				models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
 			continue
 		}
 
 		if err := tools.EnvmanAddEnvs(configs.InputEnvstorePath, *environments); err != nil {
 			runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-				"", models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
+				models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
 			continue
 		}
 
 		// Get step id & version data
 		compositeStepIDStr, workflowStep, err := models.GetStepIDStepDataPair(stepListItm)
 		if err != nil {
 			runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-				"", models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
+				models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
 			continue
 		}
 		stepInfoPtr.ID = compositeStepIDStr
@@ -653,7 +653,7 @@ func (r WorkflowRunner) activateAndRunSteps(
 		stepIDData, err := models.CreateStepIDDataFromString(compositeStepIDStr, defaultStepLibSource)
 		if err != nil {
 			runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-				"", models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
+				models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
 			continue
 		}
 		stepInfoPtr.ID = stepIDData.IDorURI
@@ -671,7 +671,7 @@ func (r WorkflowRunner) activateAndRunSteps(
 		stepYMLPth, origStepYMLPth, err := activator.activateStep(stepIDData, &buildRunResults, stepDir, configs.BitriseWorkDirPath, &workflowStep, &stepInfoPtr)
 		if err != nil {
 			runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-				"", models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
+				models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
 			continue
 		}
 
@@ -688,15 +688,15 @@ func (r WorkflowRunner) activateAndRunSteps(
 					ymlPth = origStepYMLPth
 				}
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-					"", models.StepRunStatusCodePreparationFailed, 1, fmt.Errorf("failed to parse step definition (%s): %s", ymlPth, err),
+					models.StepRunStatusCodePreparationFailed, 1, fmt.Errorf("failed to parse step definition (%s): %s", ymlPth, err),
 					isLastStep, true, map[string]string{}, stepStartedProperties)
 				continue
 			}
 
 			mergedStep, err = models.MergeStepWith(specStep, workflowStep)
 			if err != nil {
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, stepmanModels.StepModel{}, stepInfoPtr, stepIdxPtr,
-					"", models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
+					models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, true, map[string]string{}, stepStartedProperties)
 				continue
 			}
 		}
@@ -741,20 +741,20 @@ func (r WorkflowRunner) activateAndRunSteps(
 			envList, err := tools.EnvmanReadEnvList(configs.InputEnvstorePath)
 			if err != nil {
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-					*mergedStep.RunIf, models.StepRunStatusCodePreparationFailed, 1, fmt.Errorf("EnvmanReadEnvList failed, err: %s", err),
+					models.StepRunStatusCodePreparationFailed, 1, fmt.Errorf("EnvmanReadEnvList failed, err: %s", err),
 					isLastStep, false, map[string]string{}, stepStartedProperties)
 				continue
 			}
 
 			isRun, err := bitrise.EvaluateTemplateToBool(*mergedStep.RunIf, configs.IsCIMode, configs.IsPullRequestMode, buildRunResults, envList)
 			if err != nil {
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-					*mergedStep.RunIf, models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, false, map[string]string{}, stepStartedProperties)
+					models.StepRunStatusCodePreparationFailed, 1, err, isLastStep, false, map[string]string{}, stepStartedProperties)
 				continue
 			}
 			if !isRun {
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-					*mergedStep.RunIf, models.StepRunStatusCodeSkippedWithRunIf, 0, err, isLastStep, false, map[string]string{}, stepStartedProperties)
+					models.StepRunStatusCodeSkippedWithRunIf, 0, err, isLastStep, false, map[string]string{}, stepStartedProperties)
 				continue
 			}
 		}
@@ -768,7 +768,7 @@ func (r WorkflowRunner) activateAndRunSteps(
 
 		if buildRunResults.IsBuildFailed() && !isAlwaysRun {
 			runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-				*mergedStep.RunIf, models.StepRunStatusCodeSkipped, 0, err, isLastStep, false, map[string]string{}, stepStartedProperties)
+				models.StepRunStatusCodeSkipped, 0, err, isLastStep, false, map[string]string{}, stepStartedProperties)
 		} else {
 			// beside of the envs coming from the current parent process these will be added as an extra
 			var additionalEnvironments []envmanModels.EnvironmentItemModel
@@ -807,7 +807,7 @@ func (r WorkflowRunner) activateAndRunSteps(
 			}, envSource)
 			if err != nil {
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-					*mergedStep.RunIf, models.StepRunStatusCodePreparationFailed, 1,
+					models.StepRunStatusCodePreparationFailed, 1,
 					fmt.Errorf("failed to prepare step environment variables: %s", err),
 					isLastStep, false, map[string]string{}, stepStartedProperties)
 				continue
@@ -818,7 +818,7 @@ func (r WorkflowRunner) activateAndRunSteps(
 				sensitiveEnvs, err := getSensitiveEnvs(stepDeclaredEnvironments, expandedStepEnvironment)
 				if err != nil {
 					runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-						*mergedStep.RunIf, models.StepRunStatusCodePreparationFailed, 1,
+						models.StepRunStatusCodePreparationFailed, 1,
 						fmt.Errorf("failed to get sensitive inputs: %s", err),
 						isLastStep, false, map[string]string{}, stepStartedProperties)
 					continue
@@ -830,7 +830,7 @@ func (r WorkflowRunner) activateAndRunSteps(
 			redactedStepInputs, redactedOriginalInputs, err := redactStepInputs(expandedStepEnvironment, mergedStep.Inputs, stepSecrets)
 			if err != nil {
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-					*mergedStep.RunIf, models.StepRunStatusCodePreparationFailed, 1,
+					models.StepRunStatusCodePreparationFailed, 1,
 					fmt.Errorf("failed to redact step inputs: %s", err),
 					isLastStep, false, map[string]string{}, stepStartedProperties)
 				continue
@@ -860,14 +860,14 @@ func (r WorkflowRunner) activateAndRunSteps(
 			if err != nil {
 				if *mergedStep.IsSkippable {
 					runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-						*mergedStep.RunIf, models.StepRunStatusCodeFailedSkippable, exit, err, isLastStep, false, redactedStepInputs, stepIDProperties)
+						models.StepRunStatusCodeFailedSkippable, exit, err, isLastStep, false, redactedStepInputs, stepIDProperties)
 				} else {
 					runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-						*mergedStep.RunIf, models.StepRunStatusCodeFailed, exit, err, isLastStep, false, redactedStepInputs, stepIDProperties)
+						models.StepRunStatusCodeFailed, exit, err, isLastStep, false, redactedStepInputs, stepIDProperties)
 				}
 			} else {
 				runResultCollector.registerStepRunResults(&buildRunResults, stepExecutionID, stepStartTime, mergedStep, stepInfoPtr, stepIdxPtr,
-					*mergedStep.RunIf, models.StepRunStatusCodeSuccess, 0, nil, isLastStep, false, redactedStepInputs, stepIDProperties)
+					models.StepRunStatusCodeSuccess, 0, nil, isLastStep, false, redactedStepInputs, stepIDProperties)
 			}
 		}
 	}