feat: moving some cmd logs to debug (#2359)

* feat: moving some cmd logs to debug

Signed-off-by: Carlos Alexandro Becker <caarlos0@gmail.com>

* feat: moving some cmd logs to debug

Signed-off-by: Carlos Alexandro Becker <caarlos0@gmail.com>

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
 }
 

internal/gio/doc.go

@@ -0,0 +1,2 @@
+// Package gio provides io functions for GoReleaser.
+package gio

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)
+}

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)
+}

internal/logext/testdata/TestWriter/debug/0.txt.golden

@@ -0,0 +1,2 @@
+      • foo                       foo=bar
+      • bar                       foo=bar

internal/logext/testdata/TestWriter/debug/1.txt.golden

@@ -0,0 +1,2 @@
+      ⨯ foo                       foo=bar
+      ⨯ bar                       foo=bar

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")))
+}

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())
+			})
+		}
+	})
 }

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

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())
 }

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

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
 }

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)
 	}