feat: best-effort error log extraction (#442)

Author: reubeno

go.mod

@@ -19,6 +19,7 @@ require (
 	github.com/charmbracelet/x/term v0.2.2
 	github.com/creachadair/tomledit v0.0.29
 	github.com/docker/docker v28.5.2+incompatible
+	github.com/fatih/color v1.18.0
 	github.com/gkampitakis/go-snaps v0.5.19
 	github.com/go-playground/validator/v10 v10.30.1
 	github.com/google/renameio v1.0.1
@@ -79,7 +80,6 @@ require (
 	github.com/docker/go-units v0.5.0 // indirect
 	github.com/ebitengine/purego v0.8.4 // indirect
 	github.com/erikgeiser/coninput v0.0.0-20211004153227-1c3628e74d0f // indirect
-	github.com/fatih/color v1.18.0 // indirect
 	github.com/felixge/httpsnoop v1.0.4 // indirect
 	github.com/fsnotify/fsnotify v1.9.0 // indirect
 	github.com/gabriel-vasile/mimetype v1.4.12 // indirect

internal/app/azldev/core/componentbuilder/componentbuilder.go

@@ -9,9 +9,11 @@ import (
 	"context"
 	"fmt"
 	"log/slog"
+	"os"
 	"path"
 	"strings"
 
+	"github.com/fatih/color"
 	"github.com/gim-home/azldev-preview/internal/app/azldev/core/components"
 	"github.com/gim-home/azldev-preview/internal/app/azldev/core/sources"
 	"github.com/gim-home/azldev-preview/internal/app/azldev/core/workdir"
@@ -234,6 +236,9 @@ func (b *Builder) buildRPM(
 	if err != nil {
 		slog.Error("failed to build RPM", "logs", tempRPMDir)
 
+		// Make a best-effort attempt to find relevant details from failure logs.
+		displayPossiblyRelevantFailureLogs(b.fs, buildEnv, tempRPMDir)
+
 		return outputRPMPaths, fmt.Errorf("failed to build rpm:\n%w", err)
 	}
 
@@ -271,3 +276,39 @@ func (b *Builder) copyRPMsToOutputDir(inputDir, outputRPMDir string) ([]string,
 
 	return outputRPMPaths, nil
 }
+
+func displayPossiblyRelevantFailureLogs(fs opctx.FS, buildEnv buildenv.RPMAwareBuildEnv, mockOutputDirPath string) {
+	details := buildEnv.TryGetFailureDetails(fs, mockOutputDirPath)
+	if details == nil {
+		return
+	}
+
+	color.Set(color.FgHiBlack)
+
+	if len(details.LastRPMBuildLogLines) > 0 {
+		color.Set(color.Italic)
+		fmt.Fprintf(os.Stderr, "Last %d RPM build log lines: ────────────────────────────────────────────\n",
+			len(details.LastRPMBuildLogLines))
+		color.Set(color.ResetItalic)
+
+		for _, line := range details.LastRPMBuildLogLines {
+			fmt.Fprintf(os.Stderr, "  │ %s\n", line)
+		}
+
+		fmt.Fprintf(os.Stderr, "  └──────────────────────────────────────────────────────────────────────\n")
+	}
+
+	if len(details.RPMBuildErrors) > 0 {
+		color.Set(color.Italic)
+		fmt.Fprintf(os.Stderr, "RPM build errors: ───────────────────────────────────────────────────────\n")
+		color.Set(color.ResetItalic)
+
+		for _, buildError := range details.RPMBuildErrors {
+			fmt.Fprintf(os.Stderr, "  │ %s\n", buildError)
+		}
+
+		fmt.Fprintf(os.Stderr, "  └──────────────────────────────────────────────────────────────────────\n")
+	}
+
+	color.Unset()
+}

internal/buildenv/buildenv.go

@@ -39,6 +39,10 @@ type SRPMBuildOptions = mock.SRPMBuildOptions
 // using an [RPMAwareBuildEnv].
 type RPMBuildOptions = mock.RPMBuildOptions
 
+// RPMBuildLogDetails encapsulates details extracted from RPM build logs that may be relevant to
+// understanding the cause of a build failure.
+type RPMBuildLogDetails = mock.BuildLogDetails
+
 // RPMAwareBuildEnv is an interface that extends the [BuildEnv] interface for the subset of build
 // environments that provide native support RPM build operations.
 type RPMAwareBuildEnv interface {
@@ -49,6 +53,11 @@ type RPMAwareBuildEnv interface {
 
 	// BuildRPM uses this build environment to build binary RPM packages from the provided SRPM package.
 	BuildRPM(ctx context.Context, srpmPath, outputDirPath string, options RPMBuildOptions) error
+
+	// TryGetFailureDetails makes a best-effort attempt to extract details from build logs that may be
+	// relevant to understanding the cause of a build failure. This is intended to be called after a build
+	// failure to glean any insights we can from logs about why the failure might have occurred.
+	TryGetFailureDetails(fs opctx.FS, outputDirPath string) (details *RPMBuildLogDetails)
 }
 
 // RunOptions encapsulate options that may be specified at runtime when executing

internal/buildenv/buildenv_testutils/buildenv_mocks.go

@@ -98,6 +98,13 @@ func (r *MockRoot) BuildRPM(ctx context.Context, srpmPath, outputDirPath string,
 	return r.mockRunner.BuildRPM(ctx, srpmPath, outputDirPath, options)
 }
 
+// TryGetFailureDetails makes a best-effort attempt to extract details from build logs that may be
+// relevant to understanding the cause of a build failure. This is intended to be called after a build
+// failure to glean any insights we can from logs about why the failure might have occurred.
+func (r *MockRoot) TryGetFailureDetails(fs opctx.FS, outputDirPath string) (details *RPMBuildLogDetails) {
+	return r.mockRunner.TryGetFailureDetails(fs, outputDirPath)
+}
+
 func (r *MockRoot) GetInfo() BuildEnvInfo {
 	// Return stubbed info for now. When we support parallel mock with separate roots, we will fill this out
 	// correctly.

internal/buildenv/mockroot.go

@@ -15,7 +15,9 @@ import (
 	"strings"
 
 	"github.com/brunoga/deep"
+	"github.com/fatih/color"
 	"github.com/gim-home/azldev-preview/internal/global/opctx"
+	"github.com/gim-home/azldev-preview/internal/utils/fileutils"
 	"github.com/gim-home/azldev-preview/internal/utils/hostinfo"
 	"github.com/kballard/go-shellquote"
 	"github.com/samber/lo"
@@ -60,6 +62,17 @@ type Runner struct {
 	rootDir string // optional
 }
 
+// BuildLogDetails encapsulates details extracted from mock build logs that may be relevant to
+// understanding the cause of a build failure.
+type BuildLogDetails struct {
+	// RPMBuildErrors is a list of error messages extracted from mock build logs.
+	RPMBuildErrors []string
+
+	// LastRPMBuildLogLines is a list of the last lines of the mock build log, which may contain
+	// relevant context about why a build failure occurred.
+	LastRPMBuildLogLines []string
+}
+
 type bindMountRequest struct {
 	hostPath     string
 	mockRootPath string
@@ -301,7 +314,6 @@ func (r *Runner) BuildSRPM(
 
 	cmd := exec.CommandContext(ctx, MockBinary, args...)
 	cmd.Stdout = os.Stdout
-	cmd.Stderr = os.Stderr
 
 	extcmd, err := r.cmdFactory.Command(cmd)
 	if err != nil {
@@ -313,7 +325,7 @@ func (r *Runner) BuildSRPM(
 	}
 
 	// Watch output logs in real-time so we can asynchronously synthesize progress updates.
-	err = addMockLogListeners(r.eventListener, extcmd, outputDirPath)
+	err = addMockCmdListeners(r.eventListener, extcmd, outputDirPath)
 	if err != nil {
 		return err
 	}
@@ -383,7 +395,6 @@ func (r *Runner) BuildRPM(ctx context.Context, srpmPath, outputDirPath string, o
 	// being passed through.
 	cmd := exec.CommandContext(ctx, MockBinary, args...)
 	cmd.Stdout = os.Stdout
-	cmd.Stderr = os.Stderr
 
 	extcmd, err := r.cmdFactory.Command(cmd)
 	if err != nil {
@@ -393,7 +404,7 @@ func (r *Runner) BuildRPM(ctx context.Context, srpmPath, outputDirPath string, o
 	extcmd = extcmd.SetLongRunning("Waiting for mock (building RPM)...")
 
 	// Watch output logs in real-time so we can asynchronously synthesize progress updates.
-	err = addMockLogListeners(r.eventListener, extcmd, outputDirPath)
+	err = addMockCmdListeners(r.eventListener, extcmd, outputDirPath)
 	if err != nil {
 		return err
 	}
@@ -413,14 +424,30 @@ func (r *Runner) BuildRPM(ctx context.Context, srpmPath, outputDirPath string, o
 // will only run for the duration of mock's invocation, allowing us to get insights
 // into what's happening *inside* mock while we're otherwise opaquely blocking on its
 // execution.
-func addMockLogListeners(eventListener opctx.EventListener, extcmd opctx.Cmd, outputDirPath string) error {
+func addMockCmdListeners(eventListener opctx.EventListener, extcmd opctx.Cmd, outputDirPath string) error {
+	// Color-code stderr lines.
+	err := extcmd.SetRealTimeStderrListener(func(ctx context.Context, line string) {
+		if strings.HasPrefix(line, "No matching package to install:") {
+			color.Set(color.FgHiYellow)
+		} else {
+			color.Set(color.FgHiBlack, color.Italic)
+		}
+
+		defer color.Unset()
+
+		fmt.Fprintf(os.Stderr, "%s\n", line)
+	})
+	if err != nil {
+		return fmt.Errorf("failed to setup mock stderr listener: %w", err)
+	}
+
 	// Messages we care about in 'state.log' will look something like the following (without the indent):
 	//     2021-05-19 16:20:11,859 - Start: rpmbuild test-1.0.0.src.rpm
 	stateLogRe := regexp.MustCompile(`^[^ ]+ [^ ]+ - (.*)$`)
 
 	// Watch well-known log 'state.log', which gives us very high-level information
 	// about where we are in the mock build process.
-	err := extcmd.AddRealTimeFileListener(
+	err = extcmd.AddRealTimeFileListener(
 		filepath.Join(outputDirPath, "state.log"),
 		func(_ context.Context, line string) {
 			if matches := stateLogRe.FindStringSubmatch(line); len(matches) > 1 {
@@ -619,3 +646,46 @@ func (r *Runner) getBaseArgs() (args []string) {
 
 	return args
 }
+
+// TryGetFailureDetails makes a best-effort attempt to extract details from mock build logs that may be
+// relevant to understanding the cause of a build failure. This is intended to be called after a build
+// failure to glean any insights we can from mock's logs about why the failure might have occurred.
+func (r *Runner) TryGetFailureDetails(fs opctx.FS, outputDirPath string) (details *BuildLogDetails) {
+	const maxContextLinesToCapture = 10
+
+	details = &BuildLogDetails{}
+
+	// Go through build.log.
+	buildLogPath := filepath.Join(outputDirPath, "build.log")
+	buildLogBytes, _ := fileutils.ReadFile(fs, buildLogPath)
+	buildLogLines := strings.Split(string(buildLogBytes), "\n")
+
+	rpmBuildErrorsStartIndex := -1
+	rpmBuildErrorsEndIndex := -1
+
+	for lineIndex, line := range buildLogLines {
+		if strings.HasPrefix(line, "RPM build errors:") {
+			rpmBuildErrorsStartIndex = lineIndex + 1
+		} else if strings.HasPrefix(line, "EXCEPTION:") {
+			rpmBuildErrorsEndIndex = lineIndex
+		}
+	}
+
+	// If we see evidence of "RPM build errors", then try to capture relevant lines.
+	if rpmBuildErrorsStartIndex > 0 {
+		contextEndIndex := rpmBuildErrorsStartIndex - 1
+
+		if rpmBuildErrorsEndIndex < 0 {
+			rpmBuildErrorsEndIndex = len(buildLogLines)
+		}
+
+		details.RPMBuildErrors = buildLogLines[rpmBuildErrorsStartIndex:rpmBuildErrorsEndIndex]
+
+		contextLinesToCapture := min(maxContextLinesToCapture, contextEndIndex)
+		contextStartIndex := contextEndIndex - contextLinesToCapture
+
+		details.LastRPMBuildLogLines = buildLogLines[contextStartIndex:contextEndIndex]
+	}
+
+	return details
+}