From 16ce5eca5929f65de5cb70cfab1b93f2d5ae20cf Mon Sep 17 00:00:00 2001 From: Bryce Lampe Date: Tue, 16 Apr 2024 23:08:57 -0700 Subject: [PATCH] Improve logging --- provider/internal/cli.go | 32 ++++++++--- provider/internal/client.go | 33 ++++++------ provider/internal/client_test.go | 93 +++++++++++++++++++++++++++++++- provider/internal/index.go | 2 +- 4 files changed, 132 insertions(+), 28 deletions(-) diff --git a/provider/internal/cli.go b/provider/internal/cli.go index 7a1ab95..c48829d 100644 --- a/provider/internal/cli.go +++ b/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 - r, w *os.File // stdout - err bytes.Buffer // stderr - done chan struct{} // signaled when all logs have been forwarded to the engine. + in string // stdin + r, w *os.File // stdout + err bytes.Buffer // stderr + 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(err, c.r.Close()) + err := errors.Join(c.w.Close(), 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) +} diff --git a/provider/internal/client.go b/provider/internal/client.go index a89a41a..34ef2fd 100644 --- a/provider/internal/client.go +++ b/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) diff --git a/provider/internal/client_test.go b/provider/internal/client_test.go index 35e3710..ba6c39f 100644 --- a/provider/internal/client_test.go +++ b/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 { diff --git a/provider/internal/index.go b/provider/internal/index.go index 2002513..ab063a0 100644 --- a/provider/internal/index.go +++ b/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 {