diff --git a/bib/pkg/progress/export_test.go b/bib/pkg/progress/export_test.go index b2fd6f0..26d0c57 100644 --- a/bib/pkg/progress/export_test.go +++ b/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 } diff --git a/bib/pkg/progress/progress.go b/bib/pkg/progress/progress.go index 691faf2..371ba36 100644 --- a/bib/pkg/progress/progress.go +++ b/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) } } diff --git a/bib/pkg/progress/progress_test.go b/bib/pkg/progress/progress_test.go index 3e935af..f1621c7 100644 --- a/bib/pkg/progress/progress_test.go +++ b/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()) +} diff --git a/bib/pkg/progress/syncwriter.go b/bib/pkg/progress/syncwriter.go new file mode 100644 index 0000000..f9ca783 --- /dev/null +++ b/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) +} diff --git a/bib/pkg/progress/syncwriter_test.go b/bib/pkg/progress/syncwriter_test.go new file mode 100644 index 0000000..32c3757 --- /dev/null +++ b/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()) +}