progress: add new BuildLog option

This commit adds a new `BuildLog` option to the `OSBuildOptions`
that can be used to generate a streamed buildlog (e.g. to a file
or a websocket).

This will be used in `ibcli` with a new `--with-buildlog` option.

bib/pkg/progress/export_test.go

@@ -10,6 +10,18 @@ type (
 	VerboseProgressBar  = verboseProgressBar
 )
 
+var (
+	NewSyncedWriter = newSyncedWriter
+)
+
+func MockOsStdout(w io.Writer) (restore func()) {
+	saved := osStdout
+	osStdout = func() io.Writer { return w }
+	return func() {
+		osStdout = saved
+	}
+}
+
 func MockOsStderr(w io.Writer) (restore func()) {
 	saved := osStderr
 	osStderr = func() io.Writer { return w }

bib/pkg/progress/progress.go

@@ -8,6 +8,7 @@ import (
 	"os"
 	"os/exec"
 	"strings"
+	"sync"
 	"syscall"
 	"time"
 
@@ -32,6 +33,9 @@ var (
 // Used for testing, this must be a function (instead of the usual
 // "var osStderr = os.Stderr" so that higher level libraries can test
 // this code by replacing "os.Stderr", e.g. testutil.CaptureStdio()
+var osStdout = func() io.Writer {
+	return os.Stdout
+}
 var osStderr = func() io.Writer {
 	return os.Stderr
 }
@@ -321,6 +325,9 @@ type OSBuildOptions struct {
 	StoreDir  string
 	OutputDir string
 	ExtraEnv  []string
+
+	// BuildLog writes the osbuild output to the given writer
+	BuildLog io.Writer
 }
 
 // XXX: merge variant back into images/pkg/osbuild/osbuild-exec.go
@@ -345,8 +352,52 @@ func RunOSBuild(pb ProgressBar, manifest []byte, exports []string, opts *OSBuild
 }
 
 func runOSBuildNoProgress(pb ProgressBar, manifest []byte, exports []string, opts *OSBuildOptions) error {
-	_, err := osbuild.RunOSBuild(manifest, opts.StoreDir, opts.OutputDir, exports, nil, opts.ExtraEnv, false, os.Stderr)
-	return err
+	var stdout, stderr io.Writer
+
+	var writeMu sync.Mutex
+	if opts.BuildLog == nil {
+		// No external build log requested and we won't need an
+		// internal one because all output goes directly to
+		// stdout/stderr. This is for maximum compatibility with
+		// the existing bootc-image-builder in "verbose" mode
+		// where stdout, stderr come directly from osbuild.
+		stdout = osStdout()
+		stderr = osStderr()
+	} else {
+		// There is a slight wrinkle here: when requesting a
+		// buildlog we can no longer write to separate
+		// stdout/stderr streams without being racy and give
+		// potential out-of-order output (which is very bad
+		// and confusing in a log). The reason is that if
+		// cmd.Std{out,err} are different "go" will start two
+		// go-routine to monitor/copy those are racy when both
+		// stdout,stderr output happens close together
+		// (TestRunOSBuildWithBuildlog demos that). We cannot
+		// have our cake and eat it so here we need to combine
+		// osbuilds stderr into our stdout.
+		mw := newSyncedWriter(&writeMu, io.MultiWriter(osStdout(), opts.BuildLog))
+		stdout = mw
+		stderr = mw
+	}
+
+	cmd := exec.Command(
+		osbuildCmd,
+		"--store", opts.StoreDir,
+		"--output-directory", opts.OutputDir,
+		"-",
+	)
+	for _, export := range exports {
+		cmd.Args = append(cmd.Args, "--export", export)
+	}
+
+	cmd.Env = append(os.Environ(), opts.ExtraEnv...)
+	cmd.Stdin = bytes.NewBuffer(manifest)
+	cmd.Stdout = stdout
+	cmd.Stderr = stderr
+	if err := cmd.Run(); err != nil {
+		return fmt.Errorf("error running osbuild: %w", err)
+	}
+	return nil
 }
 
 var osbuildCmd = "osbuild"
@@ -372,10 +423,20 @@ func runOSBuildWithProgress(pb ProgressBar, manifest []byte, exports []string, o
 	}
 
 	var stdio bytes.Buffer
+	var mw, buildLog io.Writer
+	var writeMu sync.Mutex
+	if opts.BuildLog != nil {
+		mw = newSyncedWriter(&writeMu, io.MultiWriter(&stdio, opts.BuildLog))
+		buildLog = newSyncedWriter(&writeMu, opts.BuildLog)
+	} else {
+		mw = &stdio
+		buildLog = io.Discard
+	}
+
 	cmd.Env = append(os.Environ(), opts.ExtraEnv...)
 	cmd.Stdin = bytes.NewBuffer(manifest)
-	cmd.Stdout = &stdio
-	cmd.Stderr = &stdio
+	cmd.Stdout = mw
+	cmd.Stderr = mw
 	cmd.ExtraFiles = []*os.File{wp}
 
 	osbuildStatus := osbuild.NewStatusScanner(rp)
@@ -425,12 +486,15 @@ func runOSBuildWithProgress(pb ProgressBar, manifest []byte, exports []string, o
 			pb.SetMessagef(st.Message)
 		}
 
-		// keep all messages/traces for better error reporting
+		// keep internal log for error reporting, forward to
+		// external build log
 		if st.Message != "" {
 			tracesMsgs = append(tracesMsgs, st.Message)
+			fmt.Fprintln(buildLog, st.Message)
 		}
 		if st.Trace != "" {
 			tracesMsgs = append(tracesMsgs, st.Trace)
+			fmt.Fprintln(buildLog, st.Trace)
 		}
 	}
 

bib/pkg/progress/progress_test.go

@@ -200,3 +200,66 @@ done
 	}
 	assert.True(t, pathExists(signalDeliveredMarkerPath))
 }
+
+func TestRunOSBuildWithBuildlogTerm(t *testing.T) {
+	restore := progress.MockOsbuildCmd(makeFakeOsbuild(t, `
+echo osbuild-stdout-output
+>&2 echo osbuild-stderr-output
+
+# without the sleep this is racy as two different go routines poll
+# this does not matter (much) in practise because osbuild output and
+# stage output are using the syncedMultiWriter so output is not garbled
+sleep 0.1
+>&3 echo '{"message": "osbuild-stage-message"}'
+`))
+	defer restore()
+
+	var fakeStdout, fakeStderr bytes.Buffer
+	restore = progress.MockOsStdout(&fakeStdout)
+	defer restore()
+	restore = progress.MockOsStderr(&fakeStderr)
+	defer restore()
+
+	pbar, err := progress.New("term")
+	assert.NoError(t, err)
+
+	var buildLog bytes.Buffer
+	opts := &progress.OSBuildOptions{
+		BuildLog: &buildLog,
+	}
+	err = progress.RunOSBuild(pbar, []byte(`{"fake":"manifest"}`), nil, opts)
+	assert.NoError(t, err)
+	expectedOutput := `osbuild-stdout-output
+osbuild-stderr-output
+osbuild-stage-message
+`
+	assert.Equal(t, expectedOutput, buildLog.String())
+}
+
+func TestRunOSBuildWithBuildlogVerbose(t *testing.T) {
+	restore := progress.MockOsbuildCmd(makeFakeOsbuild(t, `
+echo osbuild-stdout-output
+>&2 echo osbuild-stderr-output
+`))
+	defer restore()
+
+	var fakeStdout, fakeStderr bytes.Buffer
+	restore = progress.MockOsStdout(&fakeStdout)
+	defer restore()
+	restore = progress.MockOsStderr(&fakeStderr)
+	defer restore()
+
+	pbar, err := progress.New("verbose")
+	assert.NoError(t, err)
+
+	var buildLog bytes.Buffer
+	opts := &progress.OSBuildOptions{
+		BuildLog: &buildLog,
+	}
+	err = progress.RunOSBuild(pbar, []byte(`{"fake":"manifest"}`), nil, opts)
+	assert.NoError(t, err)
+	expectedOutput := `osbuild-stdout-output
+osbuild-stderr-output
+`
+	assert.Equal(t, expectedOutput, buildLog.String())
+}

bib/pkg/progress/syncwriter.go

@@ -0,0 +1,22 @@
+package progress
+
+import (
+	"io"
+	"sync"
+)
+
+type syncedWriter struct {
+	mu *sync.Mutex
+	w  io.Writer
+}
+
+func newSyncedWriter(mu *sync.Mutex, w io.Writer) io.Writer {
+	return &syncedWriter{mu: mu, w: w}
+}
+
+func (sw *syncedWriter) Write(p []byte) (n int, err error) {
+	sw.mu.Lock()
+	defer sw.mu.Unlock()
+
+	return sw.w.Write(p)
+}

bib/pkg/progress/syncwriter_test.go

@@ -0,0 +1,44 @@
+package progress_test
+
+import (
+	"bufio"
+	"bytes"
+	"fmt"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+
+	"github.com/osbuild/bootc-image-builder/bib/pkg/progress"
+)
+
+func TestSyncWriter(t *testing.T) {
+	var mu sync.Mutex
+	var buf bytes.Buffer
+	var wg sync.WaitGroup
+
+	for id := 0; id < 100; id++ {
+		wg.Add(1)
+		w := progress.NewSyncedWriter(&mu, &buf)
+		go func(id int) {
+			defer wg.Done()
+			for i := 0; i < 500; i++ {
+				fmt.Fprintln(w, strings.Repeat(fmt.Sprintf("%v", id%10), 60))
+				time.Sleep(10 * time.Nanosecond)
+			}
+		}(id)
+	}
+	wg.Wait()
+
+	scanner := bufio.NewScanner(&buf)
+	for {
+		if !scanner.Scan() {
+			break
+		}
+		line := scanner.Text()
+		assert.True(t, len(line) == 60, fmt.Sprintf("len %v: line: %v", len(line), line))
+	}
+	assert.NoError(t, scanner.Err())
+}