fix(log): properly set logrus level

envbuilder.go

@@ -27,6 +27,7 @@ import (
 	"github.com/coder/envbuilder/buildinfo"
 	"github.com/coder/envbuilder/constants"
 	"github.com/coder/envbuilder/git"
+	"github.com/coder/envbuilder/log/hijack"
 	"github.com/coder/envbuilder/options"
 	"github.com/go-git/go-billy/v5"
 
@@ -278,9 +279,13 @@ func Run(ctx context.Context, opts options.Options) error {
 		}
 	}
 
-	HijackLogrus(func(entry *logrus.Entry) {
+	lvl := log.LevelInfo
+	if opts.Verbose {
+		lvl = log.LevelDebug
+	}
+	hijack.Logrus(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(hijack.LogLevel(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line))
 		}
 	})
 
@@ -1050,9 +1055,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
+	}
+	hijack.Logrus(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(hijack.LogLevel(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line))
 		}
 	})
 

log/hijack/logrus.go

@@ -0,0 +1,62 @@
+package hijack
+
+import (
+	"io"
+
+	"github.com/coder/envbuilder/log"
+	"github.com/sirupsen/logrus"
+)
+
+// Logrus 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 Logrus(lvl log.Level, callback func(entry *logrus.Entry)) {
+	logrus.StandardLogger().SetOutput(io.Discard)
+	logrus.StandardLogger().SetLevel(LogrusLevel(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 LogrusLevel(lvl log.Level) logrus.Level {
+	switch lvl {
+	case log.LevelTrace:
+		return logrus.TraceLevel
+	case log.LevelDebug:
+		return logrus.DebugLevel
+	case log.LevelInfo:
+		return logrus.InfoLevel
+	case log.LevelWarn:
+		return logrus.WarnLevel
+	case log.LevelError:
+		return logrus.ErrorLevel
+	default:
+		return logrus.InfoLevel
+	}
+}
+
+func LogLevel(lvl logrus.Level) log.Level {
+	switch lvl {
+	case logrus.TraceLevel:
+		return log.LevelTrace
+	case logrus.DebugLevel:
+		return log.LevelDebug
+	case logrus.InfoLevel:
+		return log.LevelInfo
+	case logrus.WarnLevel:
+		return log.LevelWarn
+	default: // Error, Fatal, Panic
+		return log.LevelError
+	}
+}

log/hijack/logrus_test.go

@@ -0,0 +1,111 @@
+package hijack_test
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	"github.com/coder/envbuilder/log"
+	"github.com/coder/envbuilder/log/hijack"
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/require"
+)
+
+func TestLogrus_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
+	}
+
+	hijack.Logrus(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 TestLogrus_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
+	}
+
+	hijack.Logrus(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 TestLogrus_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
+	}
+
+	hijack.Logrus(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
+}