Improve logging

provider/internal/cli.go

@@ -37,6 +37,7 @@ import (
 	cp "github.com/otiai10/copy"
 	"github.com/regclient/regclient"
 	"github.com/regclient/regclient/config"
+	"github.com/sirupsen/logrus"
 
 	provider "github.com/pulumi/pulumi-go-provider"
 	"github.com/pulumi/pulumi/sdk/v3/go/common/diag"
@@ -55,10 +56,11 @@ type cli struct {
 	auths map[string]cfgtypes.AuthConfig
 	host  *host
 
-	in   string        // stdin
+	in       string        // stdin
-	r, w *os.File      // stdout
+	r, w     *os.File      // stdout
-	err  bytes.Buffer  // stderr
+	err      bytes.Buffer  // stderr
-	done chan struct{} // signaled when all logs have been forwarded to the engine.
+	dumplogs bool          // if true then tail() will re-log status messages
+	done     chan struct{} // signaled when all logs have been forwarded to the engine.
 }
 
 // Cli wraps the Docker interface for mock generation.
@@ -165,17 +167,26 @@ func (c *cli) tail(ctx provider.Context) {
 		}
 	}()
 
+	b := bytes.Buffer{}
+
 	s := bufio.NewScanner(c.r)
 	for s.Scan() {
-		ctx.LogStatus(diag.Info, s.Text())
+		text := s.Text()
+		ctx.LogStatus(diag.Info, text)
+		_, _ = b.WriteString(text + "\n")
 	}
 	ctx.LogStatus(diag.Info, "") // clear confusing "DONE" statements.
+
+	if c.dumplogs {
+		// Persist the full Docker output on error for easier debugging.
+		ctx.Log(diag.Info, b.String())
+		ctx.Log(diag.Error, c.err.String())
+	}
 }
 
 // close flushes any outstanding logs and cleans up resources.
 func (c *cli) Close() error {
-	err := c.w.Close()
+	err := errors.Join(c.w.Close(), c.r.Close())
-	err = errors.Join(err, c.r.Close())
 	if c.done != nil {
 		<-c.done
 	}
@@ -382,7 +393,7 @@ func (c *cli) exec(args, extraEnv []string) error {
 		return err
 	}
 	cmd.Args = append([]string{cmd.Args[0]}, args...)
-	cmd.Stderr = c.Err() // TODO: This is build output...
+	cmd.Stderr = c.Err()
 	cmd.Stdout = c.Out()
 	cmd.Stdin = c.In()
 
@@ -399,3 +410,8 @@ func attrcsv(typ string, m map[string]string) string {
 	}
 	return strings.Join(s, ",")
 }
+
+func init() {
+	// Disable the CLI's tendency to log randomly to stdout.
+	logrus.SetOutput(io.Discard)
+}

provider/internal/client.go

@@ -21,7 +21,6 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"io"
 	"os"
 	"path/filepath"
 	"strings"
@@ -44,7 +43,6 @@ import (
 	"github.com/regclient/regclient/types/errs"
 	"github.com/regclient/regclient/types/manifest"
 	"github.com/regclient/regclient/types/ref"
-	"github.com/sirupsen/logrus"
 
 	provider "github.com/pulumi/pulumi-go-provider"
 	"github.com/pulumi/pulumi/sdk/v3/go/common/diag"
@@ -93,9 +91,6 @@ func newDockerCLI(config *Config) (*command.DockerCli, error) {
 
 	// TODO: Log some version information for debugging.
 
-	// Disable the CLI's tendency to log randomly to stdout.
-	logrus.SetOutput(io.Discard)
-
 	return cli, nil
 }
 
@@ -130,6 +125,18 @@ func (c *cli) Build(
 	if err != nil {
 		return nil, fmt.Errorf("creating printer: %w", err)
 	}
+	defer func() {
+		// Log any warnings when we're done.
+		_ = printer.Wait()
+		for _, w := range printer.Warnings() {
+			b := &bytes.Buffer{}
+			fmt.Fprint(b, w.Short)
+			for _, d := range w.Detail {
+				fmt.Fprintf(b, "\n%s", d)
+			}
+			pctx.Log(diag.Warning, b.String())
+		}
+	}()
 
 	cacheFrom := []client.CacheOptionsEntry{}
 	for _, c := range opts.CacheFrom {
@@ -228,21 +235,10 @@ func (c *cli) Build(
 		printer,
 	)
 	if err != nil {
+		c.dumplogs = true
 		return nil, err
 	}
 
-	if printErr := printer.Wait(); printErr != nil {
-		return results[target], printErr
-	}
-	for _, w := range printer.Warnings() {
-		b := &bytes.Buffer{}
-		fmt.Fprintf(b, "%s", w.Short)
-		for _, d := range w.Detail {
-			fmt.Fprintf(b, "\n%s", d)
-		}
-		pctx.Log(diag.Warning, b.String())
-	}
-
 	return results[target], err
 }
 
@@ -272,13 +268,14 @@ func (c *cli) ManifestCreate(ctx provider.Context, push bool, target string, ref
 	cmd := commands.NewRootCmd(os.Args[0], false, c)
 
 	cmd.SetArgs(args)
+	cmd.SetErr(c.Err())
+	cmd.SetOut(c.Out())
 
 	ctx.Log(diag.Debug, fmt.Sprint("creating manifest with args", args))
 	return cmd.ExecuteContext(ctx)
 }
 
 func (c *cli) ManifestInspect(ctx provider.Context, target string) (string, error) {
-	ctx.LogStatus(diag.Info, "inspecting manifest")
 	rc := c.rc()
 
 	ref, err := ref.New(target)

provider/internal/client_test.go

@@ -15,6 +15,7 @@
 package internal
 
 import (
+	"bytes"
 	"context"
 	"os"
 	"path/filepath"
@@ -24,6 +25,8 @@ import (
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"go.uber.org/mock/gomock"
+
+	"github.com/pulumi/pulumi/sdk/v3/go/common/diag"
 )
 
 func TestAuth(t *testing.T) {
@@ -328,7 +331,7 @@ func TestInspect(t *testing.T) {
 	)
 }
 
-func TestNormalizatReference(t *testing.T) {
+func TestNormalizeReference(t *testing.T) {
 	t.Parallel()
 	tests := []struct {
 		ref     string
@@ -363,6 +366,94 @@ func TestNormalizatReference(t *testing.T) {
 	}
 }
 
+func TestBuildError(t *testing.T) {
+	t.Parallel()
+	ctrl, ctx := gomock.WithContext(context.Background(), t)
+
+	exampleContext := &BuildContext{Context: Context{Location: "../../examples/app"}}
+
+	args := ImageArgs{
+		Context: exampleContext,
+		Dockerfile: &Dockerfile{
+			Inline: "FROM alpine\nRUN echo hello\nRUN badcmd",
+		},
+	}
+	logged := bytes.Buffer{}
+
+	pctx := NewMockProviderContext(ctrl)
+	pctx.EXPECT().Done().Return(ctx.Done()).AnyTimes()
+	pctx.EXPECT().
+		Value(gomock.Any()).
+		DoAndReturn(func(key any) any { return ctx.Value(key) }).
+		AnyTimes()
+	pctx.EXPECT().Err().Return(ctx.Err()).AnyTimes()
+	pctx.EXPECT().Deadline().Return(ctx.Deadline()).AnyTimes()
+
+	pctx.EXPECT().LogStatus(gomock.Any(), gomock.Any()).AnyTimes()
+	pctx.EXPECT().Log(gomock.Any(), gomock.Any()).DoAndReturn(func(_ diag.Severity, msg string) {
+		logged.WriteString(msg)
+	}).AnyTimes()
+
+	cli := testcli(t, true)
+
+	build, err := args.toBuild(pctx, false)
+	require.NoError(t, err)
+
+	_, err = cli.Build(pctx, build)
+	assert.Error(t, err)
+
+	want := []string{
+		`RUN echo hello`,
+		`/bin/sh: badcmd: not found`,
+		`process "/bin/sh -c badcmd" did not complete successfully: exit code: 127`,
+	}
+
+	for _, want := range want {
+		assert.Contains(t, logged.String(), want)
+	}
+}
+
+func TestBuildExecError(t *testing.T) {
+	t.Parallel()
+	ctrl, _ := gomock.WithContext(context.Background(), t)
+
+	exampleContext := &BuildContext{Context: Context{Location: "../../examples/app"}}
+
+	args := ImageArgs{
+		Context: exampleContext,
+		Dockerfile: &Dockerfile{
+			Inline: "FROM alpine\nRUN echo hello\nRUN badcmd",
+		},
+		Exec: true,
+	}
+
+	pctx := NewMockProviderContext(ctrl)
+	pctx.EXPECT().Log(
+		diag.Warning,
+		"No exports were specified so the build will only remain in the local build cache. "+
+			"Use `push` to upload the image to a registry, or silence this warning with a `cacheonly` export.",
+	)
+	pctx.EXPECT().LogStatus(gomock.Any(), gomock.Any()).AnyTimes()
+
+	cli := testcli(t, true)
+
+	build, err := args.toBuild(pctx, false)
+	require.NoError(t, err)
+
+	_, err = cli.Build(pctx, build)
+	assert.Error(t, err)
+
+	want := []string{
+		`RUN echo hello`,
+		`/bin/sh: badcmd: not found`,
+		`process "/bin/sh -c badcmd" did not complete successfully: exit code: 127`,
+	}
+
+	for _, want := range want {
+		assert.Contains(t, cli.err.String(), want)
+	}
+}
+
 // testcli returns a new standalone CLI instance. Set ping to true if a live
 // daemon is required -- the test will be skipped if the daemon is not available.
 func testcli(t *testing.T, ping bool, auths ...Registry) *cli {

provider/internal/index.go

@@ -139,7 +139,7 @@ func (i *Index) Update(
 		return state, nil
 	}
 
-	ctx.Log(diag.Info, fmt.Sprintf("creating index with tag %s and sources %s", input.Tag, input.Sources))
+	ctx.Log(diag.Debug, fmt.Sprintf("creating index with tag %s and sources %s", input.Tag, input.Sources))
 
 	err = cli.ManifestCreate(ctx, input.Push, input.Tag, input.Sources...)
 	if err != nil {