Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add status reason messaging #833

Merged
merged 31 commits into from Dec 9, 2022
Merged
Show file tree
Hide file tree
Changes from 30 commits
Commits
Show all changes
31 commits
Select commit Hold shift + click to select a range
94d364b
Added step status reason messaging
vshah23 Nov 30, 2022
e822fbc
Moved status reason to result model
vshah23 Nov 30, 2022
72ca723
Fixed formatting of status reason time interval
vshah23 Dec 1, 2022
633ea76
Added unit tests for the status reason messaging.
vshah23 Dec 1, 2022
74d7f0f
Fix linter errors
vshah23 Dec 1, 2022
e67b814
Fixed nil properties
vshah23 Dec 6, 2022
e561d66
Added and utilized short reason in footer and summary titles
vshah23 Dec 6, 2022
45f9389
Removed status reason from run output and added it to footer instead
vshah23 Dec 6, 2022
5df29c9
Updated unit tests
vshah23 Dec 6, 2022
c4c8447
Fix linter error
vshah23 Dec 6, 2022
96c7e25
Updated short reason and added unit test
vshah23 Dec 7, 2022
c73bdc1
Code style
vshah23 Dec 7, 2022
da051c4
Fixed unit test
vshah23 Dec 7, 2022
a5ba8bd
Update unit tests
vshah23 Dec 7, 2022
069dfff
Update unit tests
vshah23 Dec 7, 2022
4d53b36
StatusReason -> StatusName
vshah23 Dec 7, 2022
cff54e3
Matched output to step status doc
vshah23 Dec 8, 2022
036a5d0
Fix unit tests
vshah23 Dec 8, 2022
eca7af3
Update step finished statuses (#836)
godrei Dec 8, 2022
3254390
Updated StepRunStatus Names
vshah23 Dec 8, 2022
cd3ef07
Updated unit test
vshah23 Dec 8, 2022
a0208c2
Update unit tests
vshah23 Dec 8, 2022
05c45fb
Update unit tests
vshah23 Dec 9, 2022
eefee40
Attempt to fix flakey test
vshah23 Dec 9, 2022
d3e84c9
Update trimTitle method
godrei Dec 9, 2022
5900a0a
Update step finished console log
godrei Dec 9, 2022
7f4d85f
Fix event print tests
godrei Dec 9, 2022
735d934
Replace special quotation marks
godrei Dec 9, 2022
b58b743
Restore original value of StepRunStatuses
godrei Dec 9, 2022
4b88264
PR review updates
godrei Dec 9, 2022
8796da7
Restore earlier trimTitle
godrei Dec 9, 2022
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
4 changes: 1 addition & 3 deletions _tests/integration/log_format_test.go
Expand Up @@ -150,9 +150,7 @@ func convertStepFinishedEventLog(line []byte) (string, error) {
if err != nil {
return "", err
}

eventLog.Content.InternalStatus = models.InternalStatus(eventLog.Content.Status)


var buf bytes.Buffer
logger := log.NewLogger(log.LoggerOpts{LoggerType: log.ConsoleLogger, Writer: &buf})
logger.PrintStepFinishedEvent(eventLog.Content)
Expand Down
26 changes: 15 additions & 11 deletions bitrise/print.go
Expand Up @@ -25,21 +25,25 @@ const (
//------------------------------

func trimTitle(title string, titleSuffix string, titleBoxWidth int) string {
length := len(title)
if titleSuffix != "" {
length += 1 + len(titleSuffix)
}
titleWithSuffix := combineTitleAndSuffix(title, titleSuffix)
return log.WidthConstrainedString(titleWithSuffix, titleBoxWidth)
}

if length > titleBoxWidth {
diff := length - titleBoxWidth
title = stringutil.MaxFirstCharsWithDots(title, len(title)-diff)
func combineTitleAndSuffix(title, suffix string) string {
var titleWithSuffix string

if len(title) > 0 {
titleWithSuffix = title
}

if titleSuffix == "" {
return title
if len(suffix) > 0 {
if len(titleWithSuffix) > 0 {
titleWithSuffix += " "
}
titleWithSuffix += suffix
}

return fmt.Sprintf("%s %s", title, titleSuffix)
return titleWithSuffix
}

func getTrimmedStepName(stepRunResult models.StepRunResultsModel) string {
Expand All @@ -59,7 +63,7 @@ func getTrimmedStepName(stepRunResult models.StepRunResultsModel) string {
}

suffix := ""
reason := stepRunResult.Status.Reason(stepRunResult.ExitCode)
reason := stepRunResult.Status.Name()
if reason != "" {
suffix = fmt.Sprintf("(%s)", reason)
}
Expand Down
6 changes: 3 additions & 3 deletions bitrise/print_test.go
Expand Up @@ -39,7 +39,7 @@ func TestGetTrimmedStepName(t *testing.T) {
require.Equal(t, expected, actual)
}

t.Log("failed step")
t.Log("successful step - empty title")
{
stepInfo := stepmanModels.StepInfoModel{
Step: stepmanModels.StepModel{
Expand Down Expand Up @@ -92,7 +92,7 @@ func Test_getRunningStepFooterMainSection(t *testing.T) {
ErrorStr: longStr,
ExitCode: 1,
},
expected: "| \x1b[31;1mx\x1b[0m | \x1b[31;1mThis is a very long string, this is a very l... (exit code: 1)\x1b[0m| 0.01 sec |",
expected: "| \x1b[31;1mx\x1b[0m | \x1b[31;1mThis is a very long string, this is a very long st... (Failed)\x1b[0m| 0.01 sec |",
},
{
name: "aborted step due to no output",
Expand All @@ -104,7 +104,7 @@ func Test_getRunningStepFooterMainSection(t *testing.T) {
ErrorStr: longStr,
ExitCode: 1,
},
expected: "| \x1b[31;1m/\x1b[0m | \x1b[31;1mThis is a very long string, th... (timed out due to no output)\x1b[0m| 0.01 sec |",
expected: "| \x1b[31;1m/\x1b[0m | \x1b[31;1mThis is a very long string, this is a very long st... (Failed)\x1b[0m| 0.01 sec |",
},
{
name: "successful step",
Expand Down
74 changes: 23 additions & 51 deletions cli/build_run_result_collector.go
Expand Up @@ -2,6 +2,7 @@ package cli

import (
"errors"
"fmt"
"time"

"github.com/bitrise-io/bitrise/analytics"
Expand All @@ -10,8 +11,6 @@ import (
"github.com/bitrise-io/bitrise/models"
"github.com/bitrise-io/bitrise/tools/timeoutcmd"
"github.com/bitrise-io/bitrise/utils"
"github.com/bitrise-io/go-utils/colorstring"
"github.com/bitrise-io/go-utils/errorutil"
"github.com/bitrise-io/go-utils/pointers"
coreanalytics "github.com/bitrise-io/go-utils/v2/analytics"
stepmanModels "github.com/bitrise-io/stepman/models"
Expand Down Expand Up @@ -75,25 +74,18 @@ func (r buildRunResultCollector) registerStepRunResults(
DefinitionPth: stepInfoPtr.DefinitionPth,
}

isExitStatusError := true
if err != nil {
isExitStatusError = errorutil.IsExitStatusError(err)
}

// Print step preparation errors before the step header box,
// other errors are printed within the step box.
if status == models.StepRunStatusCodePreparationFailed && err != nil {
if !isExitStatusError {
log.Errorf("Preparing Step (%s) failed: %s", pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title"), err)
}
}
Comment on lines -78 to -89
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I prefer this way when every step related error appears inside the step box. Even if technically for these step preparation errors the step was not started. But does this new behaviour needs to be coordinated with the FE team? Because previously this error was appearing as a bitrise cli error before the step start event and now the error only appears in the step finished event.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AFAIK bitrise CLI logs are not shown when structured logging is enabled, this mostly changes how the console log is presented.

if printStepHeader {
logStepStarted(stepInfoPtr, step, stepIdxPtr, stepExecutionId, stepStartTime)
}

errStr := ""
if err != nil {
errStr = err.Error()
if status == models.StepRunStatusCodePreparationFailed {
stepTitle := pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title")
errStr = fmt.Sprintf("Preparing Step (%s) failed: %s", stepTitle, err.Error())
} else {
errStr = err.Error()
}
}

stepResults := models.StepRunResultsModel{
Expand Down Expand Up @@ -121,31 +113,16 @@ func (r buildRunResultCollector) registerStepRunResults(
case models.StepRunStatusCodePreparationFailed:
buildRunResults.FailedSteps = append(buildRunResults.FailedSteps, stepResults)
case models.StepRunStatusCodeFailed:
if !isExitStatusError {
log.Errorf("Step (%s) failed: %s", pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title"), err)
}
buildRunResults.FailedSteps = append(buildRunResults.FailedSteps, stepResults)
case models.StepRunStatusCodeFailedSkippable:
if !isExitStatusError {
log.Warnf("Step (%s) failed, but was marked as skippable: %s", pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title"), err)
} else {
log.Warnf("Step (%s) failed, but was marked as skippable", pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title"))
}
buildRunResults.FailedSkippableSteps = append(buildRunResults.FailedSkippableSteps, stepResults)
case models.StepRunStatusAbortedWithCustomTimeout, models.StepRunStatusAbortedWithNoOutputTimeout:
log.Errorf("Step (%s) aborted: %s", pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title"), err)
buildRunResults.FailedSteps = append(buildRunResults.FailedSteps, stepResults)
case models.StepRunStatusCodeSkipped:
log.Warnf("A previous step failed, and this step (%s) was not marked as IsAlwaysRun, skipped", pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title"))
buildRunResults.SkippedSteps = append(buildRunResults.SkippedSteps, stepResults)
case models.StepRunStatusCodeSkippedWithRunIf:
log.Warn("The step's (" + pointers.StringWithDefault(stepInfoCopy.Step.Title, "missing title") + ") Run-If expression evaluated to false - skipping")
if runIf != "" {
log.Info("The Run-If expression was: ", colorstring.Blue(runIf))
}
buildRunResults.SkippedSteps = append(buildRunResults.SkippedSteps, stepResults)
default:
log.Error("Unknown result code")
return
}

Expand Down Expand Up @@ -173,14 +150,6 @@ func stepFinishedParamsFromResults(results models.StepRunResultsModel, stepExecu
sourceURL = *results.StepInfo.Step.SourceCodeURL
}

var errors []log.StepError
if results.ErrorStr != "" && results.Status.IsFailure() {
errors = append(errors, log.StepError{
Code: results.ExitCode,
Message: results.ErrorStr,
})
}

var stepUpdate *log.StepUpdate
updateAvailable, _ := utils.IsUpdateAvailable(results.StepInfo.Version, results.StepInfo.LatestVersion)
if updateAvailable {
Expand All @@ -200,18 +169,21 @@ func stepFinishedParamsFromResults(results models.StepRunResultsModel, stepExecu
}
}

return log.StepFinishedParams{
ExecutionId: stepExecutionId,
InternalStatus: int(results.Status),
Status: results.Status.HumanReadableStatus(),
StatusReason: results.Status.Reason(results.ExitCode),
Title: title,
RunTime: results.RunTime.Milliseconds(),
SupportURL: supportURL,
SourceCodeURL: sourceURL,
Errors: errors,
Update: stepUpdate,
Deprecation: stepDeprecation,
LastStep: isLastStep,
params := log.StepFinishedParams{
ExecutionId: stepExecutionId,
Status: results.Status.String(),
Title: title,
RunTime: results.RunTime.Milliseconds(),
SupportURL: supportURL,
SourceCodeURL: sourceURL,
Update: stepUpdate,
Deprecation: stepDeprecation,
LastStep: isLastStep,
}

statusReason, stepErrors := results.StatusReasonAndErrors()
params.StatusReason = statusReason
params.Errors = stepErrors

return params
}
7 changes: 5 additions & 2 deletions cli/run_test.go
Expand Up @@ -1630,8 +1630,11 @@ route_map:
// Then
require.NoError(t, err)
for _, expectedEvent := range test.expectedTriggeredEvents {
output := buf.String()
assert.True(t, strings.Contains(output, expectedEvent), output)
condition := func() bool {
output := buf.String()
return strings.Contains(output, expectedEvent)
}
assert.Eventuallyf(t, condition, 5*time.Second, 150*time.Millisecond, "", "")
Comment on lines +1633 to +1637
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is this new assert needed? From what I can see in the test that we save the loggers output into a buffer and run a test workflow. By the time we reach this assertion the workflow run should be over and we should have the output in the buffer. I think we do not do any concurrent operation in the cli (workflow related).

I was curious and restored the previous assertion and did 5 test runs locally and it was always passing. Is this flaky on the CI?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The test case (GivenPluginRegisteredForMultipleTriggers_ThenPluginTriggeredTwice ) is flaky on CI, here is an example build: https://app.bitrise.io/build/0e707cfb-7591-4465-b6ab-e57f6e28925f.

}
}
}
Expand Down
19 changes: 16 additions & 3 deletions cli/run_util.go
Expand Up @@ -218,14 +218,14 @@ func CreateBitriseConfigFromCLIParams(bitriseConfigBase64Data, bitriseConfigPath
bitriseConfig = config
}

isConfigVersionOK, err := versions.IsVersionGreaterOrEqual(models.Version, bitriseConfig.FormatVersion)
isConfigVersionOK, err := versions.IsVersionGreaterOrEqual(models.FormatVersion, bitriseConfig.FormatVersion)
if err != nil {
log.Warn("bitrise CLI model version: ", models.Version)
log.Warn("bitrise CLI model version: ", models.FormatVersion)
log.Warn("bitrise.yml Format Version: ", bitriseConfig.FormatVersion)
return models.BitriseDataModel{}, warnings, fmt.Errorf("Failed to compare bitrise CLI models's version with the bitrise.yml FormatVersion: %s", err)
}
if !isConfigVersionOK {
log.Warnf("The bitrise.yml has a higher Format Version (%s) than the bitrise CLI model's version (%s).", bitriseConfig.FormatVersion, models.Version)
log.Warnf("The bitrise.yml has a higher Format Version (%s) than the bitrise CLI model's version (%s).", bitriseConfig.FormatVersion, models.FormatVersion)
return models.BitriseDataModel{}, warnings, errors.New("This bitrise.yml was created with and for a newer version of bitrise CLI, please upgrade your bitrise CLI to use this bitrise.yml")
}

Expand Down Expand Up @@ -607,6 +607,7 @@ func activateAndRunSteps(
// Per step variables
stepStartTime = time.Now()
isLastStep := isLastWorkflow && (idx == len(workflow.Steps)-1)
// TODO: stepInfoPtr.Step is not a real step, only stores presentation properties (printed in the step boxes)
stepInfoPtr := stepmanModels.StepInfoModel{}
stepIdxPtr := idx

Expand Down Expand Up @@ -707,6 +708,18 @@ func activateAndRunSteps(
stepInfoPtr.Step.SourceCodeURL = pointers.NewStringPtr(*mergedStep.SourceCodeURL)
}

if mergedStep.RunIf != nil {
stepInfoPtr.Step.RunIf = pointers.NewStringPtr(*mergedStep.RunIf)
}

if mergedStep.Timeout != nil {
stepInfoPtr.Step.Timeout = pointers.NewIntPtr(*mergedStep.Timeout)
}

if mergedStep.NoOutputTimeout != nil {
stepInfoPtr.Step.NoOutputTimeout = pointers.NewIntPtr(*mergedStep.NoOutputTimeout)
}
Comment on lines +711 to +721
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These are needed because they were not set on the stepInfoPtr previously? I was trying to see where we are reading these from the stepInfoPtr but could not see it. Is this a change to just make the code technically correct?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These are needed because they were not set on the stepInfoPtr previously?

Yes, if you search for stepInfoPtr.Step. in the activateAndRunSteps func, you can see that we only set the step properties that are later used for presentation (step boxes).

stepInfoPtr is passed to the buildRunResultCollector.registerStepRunResults, which uses it for creating the stepResults:

Then the added fields are used for creating the status reason: https://github.com/bitrise-io/bitrise/blob/CI-318/cli/build_run_result_collector.go#L184


// At this point we have a filled up step info model and also have a step model which is contains the merged step
// data from the bitrise.yml and the steps step.yml.
// If the step title contains the step id or the step library as a prefix then we will take the original steps
Expand Down
2 changes: 1 addition & 1 deletion cli/version.go
Expand Up @@ -33,7 +33,7 @@ func printVersionCmd(c *cli.Context) error {
}

if fullVersion {
versionOutput.FormatVersion = models.Version
versionOutput.FormatVersion = models.FormatVersion
versionOutput.BuildNumber = version.BuildNumber
versionOutput.Commit = version.Commit
versionOutput.OS = fmt.Sprintf("%s (%s)", runtime.GOOS, runtime.GOARCH)
Expand Down
23 changes: 16 additions & 7 deletions log/event_print.go
Expand Up @@ -8,6 +8,7 @@ import (
"github.com/bitrise-io/bitrise/log/corelog"
"github.com/bitrise-io/bitrise/models"
"github.com/bitrise-io/bitrise/utils"
"github.com/bitrise-io/go-utils/colorstring"
"github.com/bitrise-io/go-utils/stringutil"
)

Expand Down Expand Up @@ -63,10 +64,10 @@ func getHeaderLine(content string) string {
}

func widthConstrainedStringWithBorder(content string, width int) string {
return fmt.Sprintf("| %s |", widthConstrainedString(content, width))
return fmt.Sprintf("| %s |", WidthConstrainedString(content, width))
}

func widthConstrainedString(content string, width int) string {
func WidthConstrainedString(content string, width int) string {
widthDiff := len(content) - width

if widthDiff < 0 {
Expand All @@ -91,9 +92,17 @@ func generateStepFinishedFooterLines(params StepFinishedParams) []string {
}

var lines []string

for _, stepError := range params.Errors {
lines = append(lines, colorstring.Red(stepError.Message))
}
if params.StatusReason != "" {
lines = append(lines, colorstring.Blue(params.StatusReason))
}
Comment on lines +96 to +101
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have to admit you tricked me with this clever solution. 😂

I set a step preparation failed error and was debugging who prints the error inside the step box because at first look it did not make sense. The step did not run and still someone printed the error there. And if I ran it with json output then there were only the step started and step finished events and nothing in between.

But then I pieced it together and realised that the step footer now prints the errors and status reason as part of the main step body. It is was tricky for me to understand because my mind thought that the step footer always starts with the step timing information.

I do not have a better solution but just wanted highlight that this might be a little bit confusing the first time you encounter it.

lines = append(lines, sectionSeparator)
lines = append(lines, mainSeparator)
lines = append(lines, getSummaryFooterRow(params.InternalStatus, params.Title, params.StatusReason, params.RunTime, deprecated))
status := models.NewStepRunStatus(params.Status)
lines = append(lines, getSummaryFooterRow(status, params.Title, status.Name(), params.RunTime, deprecated))
lines = append(lines, mainSeparator)

hasPreviousSection := false
Expand Down Expand Up @@ -132,15 +141,15 @@ func generateStepFinishedFooterLines(params StepFinishedParams) []string {
return lines
}

func getSummaryFooterRow(status int, title, reason string, duration int64, deprecated bool) string {
func getSummaryFooterRow(status models.StepRunStatus, title, reason string, duration int64, deprecated bool) string {
icon, level := transformStatusToIconAndLevel(status)
footerTitle := getFooterTitle(level, title, reason, deprecated, footerTitleBoxWidth)
executionTime := getFooterExecutionTime(duration)

return fmt.Sprintf("|%s|%s|%s|", icon, footerTitle, executionTime)
}

func transformStatusToIconAndLevel(status int) (string, corelog.Level) {
func transformStatusToIconAndLevel(status models.StepRunStatus) (string, corelog.Level) {
var icon string
var level corelog.Level

Expand Down Expand Up @@ -202,10 +211,10 @@ func getFooterTitle(level corelog.Level, title, reason string, deprecated bool,

// Deduct the deprecated prefix length and the space between them to only shorten the title
actualWidth = actualWidth - len(deprecatedPrefix) - 1
widthConstrainedTitle := widthConstrainedString(title, actualWidth)
widthConstrainedTitle := WidthConstrainedString(title, actualWidth)
title = fmt.Sprintf("%s %s", corelog.AddColor(corelog.ErrorLevel, deprecatedPrefix), corelog.AddColor(level, widthConstrainedTitle))
} else {
title = widthConstrainedString(title, actualWidth)
title = WidthConstrainedString(title, actualWidth)
title = corelog.AddColor(level, title)
}

Expand Down