gosbuild/osbuild-exec: add support for buildlog

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 supports the `--with-buildlog` option in
image-builder-cli.

With the buildlog option set, stderr is forwarded to stdout to make sure
statements appear in order. If `BuildLogMu` is set, this mutex will be
used for the synced writer which writes to both stdout and the
buildlog. Callers can use the same mutex to write statements to the same
buildlog.

The errorWriter option got removed, and callers can just use `Stdout`
and `Stderr` to set the stdout and stderr of the command.

Author: croissanne

cmd/build/main.go

@@ -136,7 +136,7 @@ func run() error {
 	fmt.Printf("Building manifest: %s\n", manifestPath)
 
 	jobOutput := filepath.Join(outputDir, buildName)
-	_, err = osbuild.RunOSBuild(mf, nil, &osbuild.OSBuildOptions{
+	_, err = osbuild.RunOSBuild(mf, &osbuild.OSBuildOptions{
 		StoreDir:    osbuildStore,
 		OutputDir:   jobOutput,
 		Exports:     imgType.Exports(),

cmd/osbuild-playground/playground.go

@@ -57,7 +57,7 @@ func RunPlayground(img image.ImageKind, d distro.Distro, arch distro.Arch, repos
 
 	store := path.Join(state_dir, "osbuild-store")
 
-	_, err = osbuild.RunOSBuild(bytes, nil, &osbuild.OSBuildOptions{
+	_, err = osbuild.RunOSBuild(bytes, &osbuild.OSBuildOptions{
 		StoreDir:    store,
 		OutputDir:   "./",
 		Exports:     manifest.GetExports(),

pkg/osbuild/export_test.go

@@ -4,7 +4,11 @@ type (
 	StatusJSON = statusJSON
 )
 
-func MockOsbuildCmd(s string) (restore func()) {
+var (
+	NewSyncedWriter = newSyncedWriter
+)
+
+func MockOSBuildCmd(s string) (restore func()) {
 	saved := osbuildCmd
 	osbuildCmd = s
 	return func() {

pkg/osbuild/osbuild-exec.go

@@ -8,6 +8,7 @@ import (
 	"os"
 	"os/exec"
 	"strings"
+	"sync"
 
 	"github.com/hashicorp/go-version"
 
@@ -34,6 +35,14 @@ type OSBuildOptions struct {
 	Checkpoints []string
 	ExtraEnv    []string
 
+	// If specified, the mutex is used for the syncwriter so the caller may write to the build
+	// log as well. Also note that in case BuildLog is specified, stderr will be combined into
+	// stdout.
+	BuildLog   io.Writer
+	BuildLogMu *sync.Mutex
+	Stdout     io.Writer
+	Stderr     io.Writer
+
 	Monitor   MonitorType
 	MonitorFD uintptr
 
@@ -73,10 +82,44 @@ func NewOSBuildCmd(manifest []byte, optsPtr *OSBuildOptions) *exec.Cmd {
 	if opts.MonitorFD != 0 {
 		cmd.Args = append(cmd.Args, fmt.Sprintf("--monitor-fd=%d", opts.MonitorFD))
 	}
+
 	if opts.JSONOutput {
 		cmd.Args = append(cmd.Args, "--json")
 	}
 
+	// Default to os stdout/stderr. This is for maximum compatibility with the existing
+	// bootc-image-builder in "verbose" mode where stdout, stderr come directly from osbuild.
+	var stdout, stderr io.Writer
+	stdout = os.Stdout
+	if opts.Stdout != nil {
+		stdout = opts.Stdout
+	}
+	cmd.Stdout = stdout
+	stderr = os.Stderr
+	if opts.Stderr != nil {
+		stderr = opts.Stderr
+	}
+	cmd.Stderr = stderr
+
+	if opts.BuildLog != nil {
+		// 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.
+		// stdout → syncw → multiw → stdoutw or os stdout
+		// stderr ↗↗↗             → buildlog
+		var mw io.Writer
+		if opts.BuildLogMu == nil {
+			opts.BuildLogMu = new(sync.Mutex)
+		}
+		mw = newSyncedWriter(opts.BuildLogMu, io.MultiWriter(stdout, opts.BuildLog))
+		cmd.Stdout = mw
+		cmd.Stderr = mw
+	}
+
 	cmd.Env = append(os.Environ(), opts.ExtraEnv...)
 	cmd.Stdin = bytes.NewBuffer(manifest)
 	return cmd
@@ -87,7 +130,7 @@ func NewOSBuildCmd(manifest []byte, optsPtr *OSBuildOptions) *exec.Cmd {
 // Note that osbuild returns non-zero when the pipeline fails. This function
 // does not return an error in this case. Instead, the failure is communicated
 // with its corresponding logs through osbuild.Result.
-func RunOSBuild(manifest []byte, errorWriter io.Writer, optsPtr *OSBuildOptions) (*Result, error) {
+func RunOSBuild(manifest []byte, optsPtr *OSBuildOptions) (*Result, error) {
 	opts := common.ValueOrEmpty(optsPtr)
 
 	if err := CheckMinimumOSBuildVersion(); err != nil {
@@ -100,11 +143,7 @@ func RunOSBuild(manifest []byte, errorWriter io.Writer, optsPtr *OSBuildOptions)
 
 	if opts.JSONOutput {
 		cmd.Stdout = &stdoutBuffer
-	} else {
-		cmd.Stdout = os.Stdout
 	}
-	cmd.Stderr = errorWriter
-
 	err := cmd.Start()
 	if err != nil {
 		return nil, fmt.Errorf("error starting osbuild: %v", err)
@@ -186,3 +225,19 @@ func OSBuildInspect(manifest []byte) ([]byte, error) {
 
 	return out, nil
 }
+
+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)
+}

pkg/osbuild/osbuild-exec_test.go

@@ -1,19 +1,24 @@
 package osbuild_test
 
 import (
+	"bufio"
+	"bytes"
 	"fmt"
 	"io"
 	"os"
 	"path/filepath"
+	"strings"
+	"sync"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/assert"
 
 	"github.com/osbuild/images/pkg/datasizes"
 	"github.com/osbuild/images/pkg/osbuild"
 )
 
-func makeFakeOsbuild(t *testing.T, content string) string {
+func makeFakeOSBuild(t *testing.T, content string) string {
 	p := filepath.Join(t.TempDir(), "fake-osbuild")
 	err := os.WriteFile(p, []byte("#!/bin/sh\n"+content), 0755)
 	assert.NoError(t, err)
@@ -98,22 +103,82 @@ func TestNewOSBuildCmdFullOptions(t *testing.T) {
 	assert.Equal(t, mf, stdin)
 }
 
-func TestRunOSBuild(t *testing.T) {
-	fakeOsbuildBinary := makeFakeOsbuild(t, `
+func TestRunOSBuildJSONOutput(t *testing.T) {
+	fakeOSBuildBinary := makeFakeOSBuild(t, `
 if [ "$1" = "--version" ]; then
     echo '90000.0'
 else
     echo '{"success": true}'
 fi
 `)
-	restore := osbuild.MockOsbuildCmd(fakeOsbuildBinary)
+	restore := osbuild.MockOSBuildCmd(fakeOSBuildBinary)
 	defer restore()
 
 	opts := &osbuild.OSBuildOptions{
 		JSONOutput: true,
 	}
-	result, err := osbuild.RunOSBuild([]byte(`{"fake":"manifest"}`), nil, opts)
+	result, err := osbuild.RunOSBuild([]byte(`{"fake":"manifest"}`), opts)
 	assert.NoError(t, err)
 	assert.NotNil(t, result)
 	assert.True(t, result.Success)
 }
+
+func TestRunOSBuildBuildLog(t *testing.T) {
+	fakeOSBuildBinary := makeFakeOSBuild(t, `
+if [ "$1" = "--version" ]; then
+    echo '90000.0'
+else
+    echo osbuild-stdout-output
+fi
+>&2 echo osbuild-stderr-output
+`)
+	restore := osbuild.MockOSBuildCmd(fakeOSBuildBinary)
+	defer restore()
+
+	var buildLog, stdout, stderr bytes.Buffer
+	opts := &osbuild.OSBuildOptions{
+		BuildLog: &buildLog,
+		Stdout:   &stdout,
+		Stderr:   &stderr,
+	}
+
+	result, err := osbuild.RunOSBuild(nil, opts)
+	assert.NoError(t, err)
+	// without json output set the result should be empty
+	assert.Empty(t, result)
+
+	assert.NoError(t, err)
+	assert.Equal(t, `osbuild-stdout-output
+osbuild-stderr-output
+`, buildLog.String())
+	assert.Equal(t, `osbuild-stdout-output
+osbuild-stderr-output
+`, stdout.String())
+	assert.Empty(t, stderr.Bytes())
+}
+
+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 := osbuild.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 res := scanner.Scan(); res; res = scanner.Scan() {
+		line := scanner.Text()
+		assert.True(t, len(line) == 60, fmt.Sprintf("len %v: line: %v", len(line), line))
+	}
+	assert.NoError(t, scanner.Err())
+}