fix(log): properly set logrus level (#327)

(cherry picked from commit 8b9ec59)

Author: johnstcn

envbuilder.go

@@ -278,9 +278,13 @@ func Run(ctx context.Context, opts options.Options) error {
 		}
 	}
 
-	HijackLogrus(func(entry *logrus.Entry) {
+	lvl := log.LevelInfo
+	if opts.Verbose {
+		lvl = log.LevelDebug
+	}
+	log.HijackLogrus(lvl, func(entry *logrus.Entry) {
 		for _, line := range strings.Split(entry.Message, "\r") {
-			opts.Logger(log.LevelInfo, "#%d: %s", stageNumber, color.HiBlackString(line))
+			opts.Logger(log.FromLogrus(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line))
 		}
 	})
 
@@ -1050,9 +1054,13 @@ func RunCacheProbe(ctx context.Context, opts options.Options) (v1.Image, error)
 		return nil, fmt.Errorf("no Dockerfile or devcontainer.json found")
 	}
 
-	HijackLogrus(func(entry *logrus.Entry) {
+	lvl := log.LevelInfo
+	if opts.Verbose {
+		lvl = log.LevelDebug
+	}
+	log.HijackLogrus(lvl, func(entry *logrus.Entry) {
 		for _, line := range strings.Split(entry.Message, "\r") {
-			opts.Logger(log.LevelInfo, "#%d: %s", stageNumber, color.HiBlackString(line))
+			opts.Logger(log.FromLogrus(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line))
 		}
 	})
 

log.go

@@ -0,0 +1,61 @@
+package log
+
+import (
+	"io"
+
+	"github.com/sirupsen/logrus"
+)
+
+// HijackLogrus hijacks the logrus logger and calls the callback for each log entry.
+// This is an abuse of logrus, the package that Kaniko uses, but it exposes
+// no other way to obtain the log entries.
+func HijackLogrus(lvl Level, callback func(entry *logrus.Entry)) {
+	logrus.StandardLogger().SetOutput(io.Discard)
+	logrus.StandardLogger().SetLevel(ToLogrus(lvl))
+	logrus.StandardLogger().SetFormatter(&logrusFormatter{
+		callback: callback,
+		empty:    []byte{},
+	})
+}
+
+type logrusFormatter struct {
+	callback func(entry *logrus.Entry)
+	empty    []byte
+}
+
+func (f *logrusFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	f.callback(entry)
+	return f.empty, nil
+}
+
+func ToLogrus(lvl Level) logrus.Level {
+	switch lvl {
+	case LevelTrace:
+		return logrus.TraceLevel
+	case LevelDebug:
+		return logrus.DebugLevel
+	case LevelInfo:
+		return logrus.InfoLevel
+	case LevelWarn:
+		return logrus.WarnLevel
+	case LevelError:
+		return logrus.ErrorLevel
+	default:
+		return logrus.InfoLevel
+	}
+}
+
+func FromLogrus(lvl logrus.Level) Level {
+	switch lvl {
+	case logrus.TraceLevel:
+		return LevelTrace
+	case logrus.DebugLevel:
+		return LevelDebug
+	case logrus.InfoLevel:
+		return LevelInfo
+	case logrus.WarnLevel:
+		return LevelWarn
+	default: // Error, Fatal, Panic
+		return LevelError
+	}
+}

log/logrus.go

@@ -0,0 +1,110 @@
+package log_test
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	"github.com/coder/envbuilder/log"
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/require"
+)
+
+func TestHijackLogrus_Info(t *testing.T) {
+	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
+	t.Cleanup(cancel)
+	messages := make(chan *logrus.Entry)
+
+	logf := func(entry *logrus.Entry) {
+		t.Logf("got msg level: %s msg: %q", entry.Level, entry.Message)
+		messages <- entry
+	}
+
+	log.HijackLogrus(log.LevelInfo, logf)
+
+	done := make(chan struct{})
+	go func() {
+		defer close(done)
+		// The following should be filtered out.
+		logrus.Trace("Tracing!")
+		logrus.Debug("Debugging!")
+		// We should receive the below.
+		logrus.Info("Testing!")
+		logrus.Warn("Warning!")
+		logrus.Error("Error!")
+	}()
+
+	require.Equal(t, "Testing!", rcvCtx(ctx, t, messages).Message)
+	require.Equal(t, "Warning!", rcvCtx(ctx, t, messages).Message)
+	require.Equal(t, "Error!", rcvCtx(ctx, t, messages).Message)
+	<-done
+}
+
+func TestHijackLogrus_Debug(t *testing.T) {
+	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
+	t.Cleanup(cancel)
+	messages := make(chan *logrus.Entry)
+
+	logf := func(entry *logrus.Entry) {
+		t.Logf("got msg level: %s msg: %q", entry.Level, entry.Message)
+		messages <- entry
+	}
+
+	log.HijackLogrus(log.LevelDebug, logf)
+
+	done := make(chan struct{})
+	go func() {
+		defer close(done)
+		// The following should be filtered out.
+		logrus.Trace("Tracing!")
+		// We should receive the below.
+		logrus.Debug("Debugging!")
+		logrus.Info("Testing!")
+		logrus.Warn("Warning!")
+		logrus.Error("Error!")
+	}()
+
+	require.Equal(t, "Debugging!", rcvCtx(ctx, t, messages).Message)
+	require.Equal(t, "Testing!", rcvCtx(ctx, t, messages).Message)
+	require.Equal(t, "Warning!", rcvCtx(ctx, t, messages).Message)
+	require.Equal(t, "Error!", rcvCtx(ctx, t, messages).Message)
+	<-done
+}
+
+func TestHijackLogrus_Error(t *testing.T) {
+	ctx, cancel := context.WithTimeout(context.Background(), time.Second)
+	t.Cleanup(cancel)
+	messages := make(chan *logrus.Entry)
+
+	logf := func(entry *logrus.Entry) {
+		t.Logf("got msg level: %s msg: %q", entry.Level, entry.Message)
+		messages <- entry
+	}
+
+	log.HijackLogrus(log.LevelError, logf)
+
+	done := make(chan struct{})
+	go func() {
+		defer close(done)
+		// The following should be filtered out.
+		logrus.Trace("Tracing!")
+		logrus.Debug("Debugging!")
+		logrus.Info("Testing!")
+		logrus.Warn("Warning!")
+		// We should receive the below.
+		logrus.Error("Error!")
+	}()
+
+	require.Equal(t, "Error!", rcvCtx(ctx, t, messages).Message)
+	<-done
+}
+
+func rcvCtx[T any](ctx context.Context, t *testing.T, ch <-chan T) (v T) {
+	t.Helper()
+	select {
+	case <-ctx.Done():
+		t.Fatal("timeout")
+	case v = <-ch:
+	}
+	return v
+}