From bf19dc1079887d31e58065771bb069953b1704d6 Mon Sep 17 00:00:00 2001 From: Carlos Alexandro Becker Date: Fri, 23 Jul 2021 08:09:29 -0300 Subject: [PATCH] feat: moving some cmd logs to debug (#2359) * feat: moving some cmd logs to debug Signed-off-by: Carlos Alexandro Becker * feat: moving some cmd logs to debug Signed-off-by: Carlos Alexandro Becker --- internal/exec/exec.go | 10 +-- internal/gio/doc.go | 2 + internal/gio/safe.go | 22 +++++ internal/gio/safe_test.go | 30 +++++++ .../testdata/TestWriter/debug/0.txt.golden | 2 + .../testdata/TestWriter/debug/1.txt.golden | 2 + internal/logext/writer.go | 81 ++++++++++++++----- internal/logext/writer_test.go | 41 +++++++++- internal/pipe/before/before.go | 21 +++-- internal/pipe/before/before_test.go | 8 ++ internal/pipe/build/build.go | 15 ++-- internal/pipe/docker/api.go | 23 ++++-- internal/pipe/sign/sign.go | 8 +- 13 files changed, 217 insertions(+), 48 deletions(-) create mode 100644 internal/gio/doc.go create mode 100644 internal/gio/safe.go create mode 100644 internal/gio/safe_test.go create mode 100644 internal/logext/testdata/TestWriter/debug/0.txt.golden create mode 100644 internal/logext/testdata/TestWriter/debug/1.txt.golden diff --git a/internal/exec/exec.go b/internal/exec/exec.go index 212c99ef0..dabce979d 100644 --- a/internal/exec/exec.go +++ b/internal/exec/exec.go @@ -77,16 +77,16 @@ func executeCommand(c *command) error { cmd.Dir = c.Dir } - entry := log.WithField("cmd", c.Args[0]) - cmd.Stderr = logext.NewErrWriter(entry) - cmd.Stdout = logext.NewWriter(entry) + fields := log.Fields{"cmd": c.Args[0]} + cmd.Stderr = logext.NewWriter(fields, logext.Error) + cmd.Stdout = logext.NewWriter(fields, logext.Info) - entry.Info("publishing") + log.WithFields(fields).Info("publishing") if err := cmd.Run(); err != nil { return fmt.Errorf("publishing: %s failed: %w", c.Args[0], err) } - log.Debugf("command %s finished successfully", c.Args[0]) + log.WithFields(fields).Debugf("command %s finished successfully", c.Args[0]) return nil } diff --git a/internal/gio/doc.go b/internal/gio/doc.go new file mode 100644 index 000000000..6ca635626 --- /dev/null +++ b/internal/gio/doc.go @@ -0,0 +1,2 @@ +// Package gio provides io functions for GoReleaser. +package gio diff --git a/internal/gio/safe.go b/internal/gio/safe.go new file mode 100644 index 000000000..6ec7cf06a --- /dev/null +++ b/internal/gio/safe.go @@ -0,0 +1,22 @@ +package gio + +import ( + "io" + "sync" +) + +// Safe wraps the given writer to be thread-safe. +func Safe(w io.Writer) io.Writer { + return &safeWriter{w: w} +} + +type safeWriter struct { + w io.Writer + m sync.Mutex +} + +func (s *safeWriter) Write(p []byte) (int, error) { + s.m.Lock() + defer s.m.Unlock() + return s.w.Write(p) +} diff --git a/internal/gio/safe_test.go b/internal/gio/safe_test.go new file mode 100644 index 000000000..c3997cfc5 --- /dev/null +++ b/internal/gio/safe_test.go @@ -0,0 +1,30 @@ +package gio + +import ( + "bytes" + "sync" + "testing" + + "github.com/stretchr/testify/require" +) + +func TestSafe(t *testing.T) { + chars := 30 + + var b bytes.Buffer + w := Safe(&b) + + var wg sync.WaitGroup + wg.Add(chars) + for i := 0; i < chars; i++ { + go func() { + s, err := w.Write([]byte("a")) + require.Equal(t, 1, s) + require.NoError(t, err) + wg.Done() + }() + } + wg.Wait() + + require.Len(t, b.String(), chars) +} diff --git a/internal/logext/testdata/TestWriter/debug/0.txt.golden b/internal/logext/testdata/TestWriter/debug/0.txt.golden new file mode 100644 index 000000000..8a456c653 --- /dev/null +++ b/internal/logext/testdata/TestWriter/debug/0.txt.golden @@ -0,0 +1,2 @@ + • foo foo=bar + • bar foo=bar diff --git a/internal/logext/testdata/TestWriter/debug/1.txt.golden b/internal/logext/testdata/TestWriter/debug/1.txt.golden new file mode 100644 index 000000000..18a36d152 --- /dev/null +++ b/internal/logext/testdata/TestWriter/debug/1.txt.golden @@ -0,0 +1,2 @@ + ⨯ foo foo=bar + ⨯ bar foo=bar diff --git a/internal/logext/writer.go b/internal/logext/writer.go index 8527eaacc..a1786a9d5 100644 --- a/internal/logext/writer.go +++ b/internal/logext/writer.go @@ -1,33 +1,72 @@ package logext -import "github.com/apex/log" +import ( + "bytes" + "io" + "strings" -// Writer writes with log.Info. -type Writer struct { - ctx *log.Entry -} + "github.com/apex/log" + "github.com/apex/log/handlers/cli" +) + +// Output type of the log output. +type Output int + +const ( + // Info usually is used with stdout. + Info Output = iota + + // Error usually is used with stderr. + Error +) // NewWriter creates a new log writer. -func NewWriter(ctx *log.Entry) Writer { - return Writer{ctx: ctx} +func NewWriter(fields log.Fields, out Output) io.Writer { + if isDebug() { + return logWriter{ + ctx: newLogger(fields), + out: out, + } + } + return io.Discard } -func (t Writer) Write(p []byte) (n int, err error) { - t.ctx.Info(string(p)) - return len(p), nil -} - -// ErrorWriter writes with log.Error. -type ErrorWriter struct { +type logWriter struct { ctx *log.Entry + out Output } -// NewErrWriter creates a new log writer. -func NewErrWriter(ctx *log.Entry) ErrorWriter { - return ErrorWriter{ctx: ctx} -} - -func (w ErrorWriter) Write(p []byte) (n int, err error) { - w.ctx.Error(string(p)) +func (w logWriter) Write(p []byte) (int, error) { + for _, line := range strings.Split(toString(p), "\n") { + switch w.out { + case Info: + w.ctx.Info(line) + case Error: + w.ctx.Error(line) + } + } return len(p), nil } + +func newLogger(fields log.Fields) *log.Entry { + handler := cli.New(cli.Default.Writer) + handler.Padding = cli.Default.Padding + 3 + logger := log.WithFields(fields) + logger.Logger.Handler = handler + return logger +} + +func isDebug() bool { + return logLevel() == log.DebugLevel +} + +func logLevel() log.Level { + if logger, ok := log.Log.(*log.Logger); ok { + return logger.Level + } + return log.InfoLevel +} + +func toString(b []byte) string { + return string(bytes.TrimSuffix(b, []byte("\n"))) +} diff --git a/internal/logext/writer_test.go b/internal/logext/writer_test.go index d76a63523..f80b48e62 100644 --- a/internal/logext/writer_test.go +++ b/internal/logext/writer_test.go @@ -1,14 +1,49 @@ package logext import ( + "bytes" + "os" + "strconv" "testing" "github.com/apex/log" + "github.com/apex/log/handlers/cli" + "github.com/goreleaser/goreleaser/internal/golden" "github.com/stretchr/testify/require" ) func TestWriter(t *testing.T) { - l, err := NewWriter(log.WithField("foo", "bar")).Write([]byte("foo bar")) - require.NoError(t, err) - require.Equal(t, 7, l) + t.Run("info", func(t *testing.T) { + for _, out := range []Output{Info, Error} { + t.Run(strconv.Itoa(int(out)), func(t *testing.T) { + t.Cleanup(func() { + cli.Default.Writer = os.Stderr + }) + var b bytes.Buffer + cli.Default.Writer = &b + l, err := NewWriter(log.Fields{"foo": "bar"}, out).Write([]byte("foo\nbar\n")) + require.NoError(t, err) + require.Equal(t, 8, l) + require.Empty(t, b.String()) + }) + } + }) + + t.Run("debug", func(t *testing.T) { + for _, out := range []Output{Info, Error} { + t.Run(strconv.Itoa(int(out)), func(t *testing.T) { + t.Cleanup(func() { + cli.Default.Writer = os.Stderr + log.SetLevel(log.InfoLevel) + }) + log.SetLevel(log.DebugLevel) + var b bytes.Buffer + cli.Default.Writer = &b + l, err := NewWriter(log.Fields{"foo": "bar"}, out).Write([]byte("foo\nbar\n")) + require.NoError(t, err) + require.Equal(t, 8, l) + golden.RequireEqualTxt(t, b.Bytes()) + }) + } + }) } diff --git a/internal/pipe/before/before.go b/internal/pipe/before/before.go index 65fa2be86..89a7175b0 100644 --- a/internal/pipe/before/before.go +++ b/internal/pipe/before/before.go @@ -2,12 +2,15 @@ package before import ( + "bytes" "fmt" + "io" "os/exec" "github.com/apex/log" "github.com/caarlos0/go-shellwords" - "github.com/fatih/color" + "github.com/goreleaser/goreleaser/internal/gio" + "github.com/goreleaser/goreleaser/internal/logext" "github.com/goreleaser/goreleaser/internal/tmpl" "github.com/goreleaser/goreleaser/pkg/context" ) @@ -33,13 +36,19 @@ func (Pipe) Run(ctx *context.Context) error { if err != nil { return err } - log.Infof("running %s", color.CyanString(step)) + cmd := exec.Command(args[0], args[1:]...) cmd.Env = ctx.Env.Strings() - out, err := cmd.CombinedOutput() - log.WithField("cmd", step).Debug(string(out)) - if err != nil { - return fmt.Errorf("hook failed: %s: %w; output: %s", step, err, string(out)) + + var b bytes.Buffer + w := gio.Safe(&b) + fields := log.Fields{"hook": step} + cmd.Stderr = io.MultiWriter(logext.NewWriter(fields, logext.Error), w) + cmd.Stdout = io.MultiWriter(logext.NewWriter(fields, logext.Info), w) + + log.WithFields(fields).Info("running") + if err := cmd.Run(); err != nil { + return fmt.Errorf("hook failed: %s: %w; output: %s", step, err, b.String()) } } return nil diff --git a/internal/pipe/before/before_test.go b/internal/pipe/before/before_test.go index 21594df58..878e25eb6 100644 --- a/internal/pipe/before/before_test.go +++ b/internal/pipe/before/before_test.go @@ -1,14 +1,22 @@ package before import ( + "os" "path/filepath" "testing" + "github.com/apex/log" "github.com/goreleaser/goreleaser/pkg/config" "github.com/goreleaser/goreleaser/pkg/context" "github.com/stretchr/testify/require" ) +func TestMain(m *testing.M) { + log.SetLevel(log.DebugLevel) + defer log.SetLevel(log.InfoLevel) + os.Exit(m.Run()) +} + func TestDescription(t *testing.T) { require.NotEmpty(t, Pipe{}.String()) } diff --git a/internal/pipe/build/build.go b/internal/pipe/build/build.go index e9da2e0f6..a9b8f2bbf 100644 --- a/internal/pipe/build/build.go +++ b/internal/pipe/build/build.go @@ -13,6 +13,7 @@ import ( "github.com/apex/log" "github.com/caarlos0/go-shellwords" + "github.com/goreleaser/goreleaser/internal/gio" "github.com/goreleaser/goreleaser/internal/ids" "github.com/goreleaser/goreleaser/internal/logext" "github.com/goreleaser/goreleaser/internal/semerrgroup" @@ -226,19 +227,23 @@ func extFor(target string, flags config.FlagArray) string { } func run(ctx *context.Context, dir string, command, env []string) error { + fields := log.Fields{ + "cmd": command, + "env": env, + } /* #nosec */ cmd := exec.CommandContext(ctx, command[0], command[1:]...) - entry := log.WithField("cmd", command) cmd.Env = env var b bytes.Buffer - cmd.Stderr = io.MultiWriter(logext.NewErrWriter(entry), &b) - cmd.Stdout = io.MultiWriter(logext.NewWriter(entry), &b) + w := gio.Safe(&b) + cmd.Stderr = io.MultiWriter(logext.NewWriter(fields, logext.Error), w) + cmd.Stdout = io.MultiWriter(logext.NewWriter(fields, logext.Info), w) if dir != "" { cmd.Dir = dir } - entry.WithField("env", env).Debug("running") + log.WithFields(fields).Debug("running") if err := cmd.Run(); err != nil { - entry.WithError(err).Debug("failed") + log.WithFields(fields).WithError(err).Debug("failed") return fmt.Errorf("%q: %w", b.String(), err) } return nil diff --git a/internal/pipe/docker/api.go b/internal/pipe/docker/api.go index c91e13dbc..0ea312ca4 100644 --- a/internal/pipe/docker/api.go +++ b/internal/pipe/docker/api.go @@ -1,11 +1,15 @@ package docker import ( + "bytes" "context" + "io" "os/exec" "sync" "github.com/apex/log" + "github.com/goreleaser/goreleaser/internal/gio" + "github.com/goreleaser/goreleaser/internal/logext" ) var ( @@ -40,12 +44,21 @@ type manifester interface { // nolint: unparam func runCommand(ctx context.Context, dir, binary string, args ...string) ([]byte, error) { + fields := log.Fields{ + "cmd": append([]string{binary}, args[0]), + "cwd": dir, + } + /* #nosec */ cmd := exec.CommandContext(ctx, binary, args...) cmd.Dir = dir - log := log.WithField("cmd", cmd.Args).WithField("cwd", cmd.Dir) - log.Debug("running") - out, err := cmd.CombinedOutput() - log.Debug(string(out)) - return out, err + + var b bytes.Buffer + w := gio.Safe(&b) + cmd.Stderr = io.MultiWriter(logext.NewWriter(fields, logext.Error), w) + cmd.Stdout = io.MultiWriter(logext.NewWriter(fields, logext.Info), w) + + log.WithFields(fields).Debug("running") + err := cmd.Run() + return b.Bytes(), err } diff --git a/internal/pipe/sign/sign.go b/internal/pipe/sign/sign.go index 8867b2e70..0bd407720 100644 --- a/internal/pipe/sign/sign.go +++ b/internal/pipe/sign/sign.go @@ -146,17 +146,19 @@ func signone(ctx *context.Context, cfg config.Sign, a *artifact.Artifact) (*arti stdin = f } + fields := log.Fields{"cmd": cfg.Cmd} + // The GoASTScanner flags this as a security risk. // However, this works as intended. The nosec annotation // tells the scanner to ignore this. // #nosec cmd := exec.CommandContext(ctx, cfg.Cmd, args...) - cmd.Stderr = logext.NewWriter(log.WithField("cmd", cfg.Cmd)) - cmd.Stdout = cmd.Stderr + cmd.Stderr = logext.NewWriter(fields, logext.Error) + cmd.Stdout = logext.NewWriter(fields, logext.Info) if stdin != nil { cmd.Stdin = stdin } - log.WithField("cmd", cmd.Args).Info("signing") + log.WithFields(fields).Info("signing") if err := cmd.Run(); err != nil { return nil, fmt.Errorf("sign: %s failed", cfg.Cmd) }