From 3686acea6b5c0be7142f4a717d8684cff847ea50 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kriszti=C3=A1n=20G=C3=B6drei?= Date: Mon, 19 Jun 2023 13:08:06 +0200 Subject: [PATCH] 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 --- analytics/tracker.go | 4 ++++ analytics/tracker_test.go | 13 ++++++++--- cli/build_run_result_collector.go | 6 ++++-- cli/run_util.go | 36 +++++++++++++++---------------- 4 files changed, 36 insertions(+), 23 deletions(-) diff --git a/analytics/tracker.go b/analytics/tracker.go index a24689e4a..a5bea31a1 100644 --- 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 index 44e9534f6..745550b6c 100644 --- 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 index bd70bfd93..c07475007 100644 --- 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 index ab3457dd2..3ceee9852 100644 --- a/cli/run_util.go +++ b/cli/run_util.go @@ -618,7 +618,7 @@ 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 } @@ -626,13 +626,13 @@ func (r WorkflowRunner) activateAndRunSteps( // 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 } @@ -640,7 +640,7 @@ func (r WorkflowRunner) activateAndRunSteps( 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,7 +688,7 @@ 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 } @@ -696,7 +696,7 @@ func (r WorkflowRunner) activateAndRunSteps( 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,7 +741,7 @@ 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 } @@ -749,12 +749,12 @@ func (r WorkflowRunner) activateAndRunSteps( 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) } } }