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

Improve error output when executing step fails #325

Merged
merged 3 commits into from
Sep 22, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,8 @@ All notable changes to `src-cli` are documented in this file.

### Changed

- Error reporting by `src campaign [preview|apply]` has been improved and now includes more information about which step failed in which repository. [#325](https://github.com/sourcegraph/src-cli/pull/325)

### Fixed

- Log files created by `src campaigns [preview|apply]` are deleted again after successful execution. This was a regression and is not new behaviour. If steps failed to execute or the `-keep-logs` flag is set the log files are not cleaned up.
Expand Down
7 changes: 2 additions & 5 deletions cmd/src/campaigns_apply.go
Original file line number Diff line number Diff line change
Expand Up @@ -63,11 +63,8 @@ Examples:
})

if err := doApply(ctx, out, svc, flags); err != nil {
out.Write("")
block := out.Block(output.Line("❌", output.StyleWarning, "Error"))
block.Write(err.Error())
block.Close()
out.Write("")
printExecutionError(out, err)
return &exitCodeError{nil, 1}
}

return nil
Expand Down
54 changes: 54 additions & 0 deletions cmd/src/campaigns_common.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,13 +3,15 @@ package main
import (
"context"
"flag"
"fmt"
"io"
"os"
"path"
"runtime"
"time"

"github.com/hashicorp/go-multierror"
"github.com/neelance/parallel"
"github.com/pkg/errors"
"github.com/sourcegraph/src-cli/internal/api"
"github.com/sourcegraph/src-cli/internal/campaigns"
Expand Down Expand Up @@ -277,3 +279,55 @@ func campaignsExecute(ctx context.Context, out *output.Output, svc *campaigns.Se

return id, url, nil
}

// printExecutionError is used to print the possible error returned by
// campaignsExecute.
func printExecutionError(out *output.Output, err error) {
out.Write("")

writeErr := func(block *output.Block, err error) {
if block == nil {
return
}

if taskErr, ok := err.(campaigns.TaskExecutionErr); ok {
block.Write(formatTaskExecutionErr(taskErr))
} else {
block.Write(err.Error())
}
}

var block *output.Block
singleErrHeader := output.Line(output.EmojiFailure, output.StyleWarning, "Error:")

if parErr, ok := err.(parallel.Errors); ok {
if len(parErr) > 1 {
block = out.Block(output.Linef(output.EmojiFailure, output.StyleWarning, "%d errors:", len(parErr)))
} else {
block = out.Block(singleErrHeader)
}

for _, e := range parErr {
writeErr(block, e)
}
} else {
block = out.Block(singleErrHeader)
writeErr(block, err)
}

if block != nil {
block.Close()
}
out.Write("")
}

func formatTaskExecutionErr(err campaigns.TaskExecutionErr) string {
return fmt.Sprintf(
"%s%s%s:\n%s\nLog: %s\n",
output.StyleBold,
err.Repository,
output.StyleReset,
err.Err,
err.Logfile,
)
}
6 changes: 1 addition & 5 deletions cmd/src/campaigns_preview.go
Original file line number Diff line number Diff line change
Expand Up @@ -41,11 +41,7 @@ Examples:

_, url, err := campaignsExecute(ctx, out, svc, flags)
if err != nil {
out.Write("")
block := out.Block(output.Line("❌", output.StyleWarning, "Error"))
block.Write(err.Error())
block.Close()
out.Write("")
printExecutionError(out, err)
return &exitCodeError{nil, 1}
}

Expand Down
21 changes: 20 additions & 1 deletion internal/campaigns/executor.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,21 @@ import (
"github.com/sourcegraph/src-cli/internal/campaigns/graphql"
)

type TaskExecutionErr struct {
Err error
Logfile string
Repository string
}

func (e TaskExecutionErr) Error() string {
return fmt.Sprintf(
"execution in %s failed: %s (see %s for details)",
e.Repository,
e.Err,
e.Logfile,
)
}

type Executor interface {
AddTask(repo *graphql.Repository, steps []Step, template *ChangesetTemplate) *TaskStatus
LogFiles() []string
Expand Down Expand Up @@ -186,7 +201,11 @@ func (x *executor) do(ctx context.Context, task *Task) (err error) {
}
defer func() {
if err != nil {
err = errors.Wrapf(err, "Error executing task. The log file can be found at:\n%s\n", log.Path())
err = TaskExecutionErr{
Err: err,
Logfile: log.Path(),
Repository: task.Repository.Name,
}
log.MarkErrored()
}
log.Close()
Expand Down
73 changes: 69 additions & 4 deletions internal/campaigns/run_steps.go
Original file line number Diff line number Diff line change
Expand Up @@ -70,7 +70,7 @@ func runSteps(ctx context.Context, client api.Client, repo *graphql.Repository,
}

for i, step := range steps {
logger.Logf("[Step %d] docker run %s", i+1, step.image)
logger.Logf("[Step %d] docker run %s %q", i+1, step.Container, step.Run)

cidFile, err := ioutil.TempFile(tempDir, prefix+"-container-id")
if err != nil {
Expand Down Expand Up @@ -120,8 +120,10 @@ func runSteps(ctx context.Context, client api.Client, repo *graphql.Repository,
}
cmd.Args = append(cmd.Args, "--", step.image, containerTemp)
cmd.Dir = volumeDir
cmd.Stdout = logger.PrefixWriter("stdout")
cmd.Stderr = logger.PrefixWriter("stderr")

var stdoutBuffer, stderrBuffer bytes.Buffer
cmd.Stdout = io.MultiWriter(&stdoutBuffer, logger.PrefixWriter("stdout"))
cmd.Stderr = io.MultiWriter(&stderrBuffer, logger.PrefixWriter("stderr"))

a, err := json.Marshal(cmd.Args)
if err != nil {
Expand All @@ -134,7 +136,16 @@ func runSteps(ctx context.Context, client api.Client, repo *graphql.Repository,
elapsed := time.Since(t0).Round(time.Millisecond)
if err != nil {
logger.Logf("[Step %d] took %s; error running Docker container: %+v", i+1, elapsed, err)
return nil, errors.Wrapf(err, "Running Docker container for image %q failed", step.image)

return nil, stepFailedErr{
Err: err,
Args: cmd.Args,
Run: step.Run,
Container: step.Container,
TmpFilename: containerTemp,
Stdout: strings.TrimSpace(stdoutBuffer.String()),
Stderr: strings.TrimSpace(stderrBuffer.String()),
}
}
logger.Logf("[Step %d] complete in %s", i+1, elapsed)

Expand Down Expand Up @@ -297,3 +308,57 @@ func probeImageForShell(ctx context.Context, image string) (shell, tempfile stri
// admit defeat and return. At least err is already in place.
return
}

type stepFailedErr struct {
Run string
Container string

TmpFilename string

Args []string
Stdout string
Stderr string

Err error
}

func (e stepFailedErr) Error() string {
var out strings.Builder

fmtRun := func(run string) string {
lines := strings.Split(run, "\n")
if len(lines) == 1 {
return lines[0]
}
return lines[0] + fmt.Sprintf("\n\t(... and %d more lines)", len(lines)-1)
}

out.WriteString(fmt.Sprintf("run: %s\ncontainer: %s\n", fmtRun(e.Run), e.Container))

printOutput := func(output string) {
for _, line := range strings.Split(output, "\n") {
if e.TmpFilename != "" {
line = strings.ReplaceAll(line, e.TmpFilename+": ", "")
}
out.WriteString("\t" + line + "\n")
}
}

if len(e.Stdout) > 0 {
out.WriteString("\nstandard out:\n")
printOutput(e.Stdout)
}

if len(e.Stderr) > 0 {
out.WriteString("\nstandard error:\n")
printOutput(e.Stderr)
}
Comment on lines +347 to +355
Copy link
Member

Choose a reason for hiding this comment

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

Do you think they should be printed separately? I don't really know many places where that's the case (CI providers, GH actions, ..) usually print everything together (and sometimes it could be confusing I guess if:

stdout: Processing resource file X.yml
stderr: Failed to process.
stdout: Processing resource file Y.yml
stdout: Done, 1 errors.

, how would I know which of the files failed. Maybe it's just me though, so leaving it up to you and approve
)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yeah, they print everything together because they stream the output, we don't. We buffer and then print. And since we buffer them separately we can't easily weave them back together to get to your example output. We'd need to record some timing information for that, but that's a hole I don't want to jump into. Or we could use a custom entity that buffers and prefixes both.

Honestly, though, I like having them separate. I hate having to dig through lines and lines of output to get to the error messages. It's something that annoys me about CI providers actually 😄

Copy link
Member

Choose a reason for hiding this comment

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

we could use the same buffer though, no? 🤔 I mean, which tool prints simultaneously on both out and err 🤔

But if you like it better, go for it, I was just scared that some tools might use the channels in a weird way that only works when they're printed next to each other, like in my sample.
Probably an unreasonable fear though 😬

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yeah, sure, we could use the same buffer, but then we'd just have everything together in one without knowing at a quick glance what's error or output. And considering how noisy some tools are... If we run into issues, we can revisit this, I think.

Copy link
Member

Choose a reason for hiding this comment

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

totally


if exitErr, ok := e.Err.(*exec.ExitError); ok {
out.WriteString(fmt.Sprintf("\nCommand failed with exit code %d.", exitErr.ExitCode()))
eseliger marked this conversation as resolved.
Show resolved Hide resolved
} else {
out.WriteString(fmt.Sprintf("\nCommand failed: %s", e.Err))
}

return out.String()
}
2 changes: 1 addition & 1 deletion internal/campaigns/service.go
Original file line number Diff line number Diff line change
Expand Up @@ -196,7 +196,7 @@ func (svc *Service) ExecuteCampaignSpec(ctx context.Context, repos []*graphql.Re
done <- struct{}{}
}
if err != nil {
return nil, errors.Wrap(err, "executing campaign spec")
return nil, err
}

// Add external changeset specs.
Expand Down
4 changes: 4 additions & 0 deletions internal/output/style.go
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,10 @@ var (
StyleWarning = Fg256Color(124)
StyleSuccess = Fg256Color(2)

StyleBold = &style{"\033[1m"}
StyleItalic = &style{"\033[3m"}
StyleUnderline = &style{"\033[4m"}

// Search-specific colors.
StyleSearchQuery = Fg256Color(68)
StyleSearchBorder = Fg256Color(239)
Expand Down