From 174bb96823f5ecb1cbe200a5309eb3a4a7ac77c2 Mon Sep 17 00:00:00 2001 From: Cian Johnston Date: Tue, 27 Aug 2024 12:36:16 +0100 Subject: [PATCH 1/4] chore: extract HijackLogrus to log/hijack package --- envbuilder.go | 5 +++-- log.go => log/hijack/logrus.go | 6 +++--- log/hijack/logrus_test.go | 27 +++++++++++++++++++++++++++ log_test.go | 19 ------------------- 4 files changed, 33 insertions(+), 24 deletions(-) rename log.go => log/hijack/logrus.go (76%) create mode 100644 log/hijack/logrus_test.go delete mode 100644 log_test.go diff --git a/envbuilder.go b/envbuilder.go index 9360fe22..cbc4ffc4 100644 --- a/envbuilder.go +++ b/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,7 +279,7 @@ func Run(ctx context.Context, opts options.Options) error { } } - HijackLogrus(func(entry *logrus.Entry) { + hijack.Logrus(func(entry *logrus.Entry) { for _, line := range strings.Split(entry.Message, "\r") { opts.Logger(log.LevelInfo, "#%d: %s", stageNumber, color.HiBlackString(line)) } @@ -1050,7 +1051,7 @@ 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) { + hijack.Logrus(func(entry *logrus.Entry) { for _, line := range strings.Split(entry.Message, "\r") { opts.Logger(log.LevelInfo, "#%d: %s", stageNumber, color.HiBlackString(line)) } diff --git a/log.go b/log/hijack/logrus.go similarity index 76% rename from log.go rename to log/hijack/logrus.go index ad476c1d..324debc8 100644 --- a/log.go +++ b/log/hijack/logrus.go @@ -1,4 +1,4 @@ -package envbuilder +package hijack import ( "io" @@ -6,10 +6,10 @@ import ( "github.com/sirupsen/logrus" ) -// HijackLogrus hijacks the logrus logger and calls the callback for each log entry. +// 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 HijackLogrus(callback func(entry *logrus.Entry)) { +func Logrus(callback func(entry *logrus.Entry)) { logrus.StandardLogger().SetOutput(io.Discard) logrus.StandardLogger().SetFormatter(&logrusFormatter{ callback: callback, diff --git a/log/hijack/logrus_test.go b/log/hijack/logrus_test.go new file mode 100644 index 00000000..fab057bb --- /dev/null +++ b/log/hijack/logrus_test.go @@ -0,0 +1,27 @@ +package hijack_test + +import ( + "context" + "testing" + "time" + + "github.com/coder/envbuilder/log/hijack" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" +) + +func TestLogrus(t *testing.T) { + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + t.Cleanup(cancel) + messages := make(chan *logrus.Entry, 1) + hijack.Logrus(func(entry *logrus.Entry) { + messages <- entry + }) + logrus.Infof("Testing!") + select { + case <-ctx.Done(): + require.FailNow(t, "timed out") + case message := <-messages: + require.Equal(t, "Testing!", message.Message) + } +} diff --git a/log_test.go b/log_test.go deleted file mode 100644 index 63d5e6cd..00000000 --- a/log_test.go +++ /dev/null @@ -1,19 +0,0 @@ -package envbuilder_test - -import ( - "testing" - - "github.com/coder/envbuilder" - "github.com/sirupsen/logrus" - "github.com/stretchr/testify/require" -) - -func TestHijackLogrus(t *testing.T) { - messages := make(chan *logrus.Entry, 1) - envbuilder.HijackLogrus(func(entry *logrus.Entry) { - messages <- entry - }) - logrus.Infof("Testing!") - message := <-messages - require.Equal(t, "Testing!", message.Message) -} From 308979b2e17ac592841a89fa86498a83261111d0 Mon Sep 17 00:00:00 2001 From: Cian Johnston Date: Tue, 27 Aug 2024 13:32:51 +0100 Subject: [PATCH 2/4] fix(log/hijack): properly set logrus level --- envbuilder.go | 16 ++++-- log/hijack/logrus.go | 36 +++++++++++++- log/hijack/logrus_test.go | 100 +++++++++++++++++++++++++++++++++++--- 3 files changed, 139 insertions(+), 13 deletions(-) diff --git a/envbuilder.go b/envbuilder.go index cbc4ffc4..d68d0a8d 100644 --- a/envbuilder.go +++ b/envbuilder.go @@ -279,9 +279,13 @@ func Run(ctx context.Context, opts options.Options) error { } } - hijack.Logrus(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)) } }) @@ -1051,9 +1055,13 @@ func RunCacheProbe(ctx context.Context, opts options.Options) (v1.Image, error) return nil, fmt.Errorf("no Dockerfile or devcontainer.json found") } - hijack.Logrus(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)) } }) diff --git a/log/hijack/logrus.go b/log/hijack/logrus.go index 324debc8..1d59932b 100644 --- a/log/hijack/logrus.go +++ b/log/hijack/logrus.go @@ -3,14 +3,16 @@ 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(callback func(entry *logrus.Entry)) { +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{}, @@ -26,3 +28,35 @@ 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 + } +} diff --git a/log/hijack/logrus_test.go b/log/hijack/logrus_test.go index fab057bb..44b32511 100644 --- a/log/hijack/logrus_test.go +++ b/log/hijack/logrus_test.go @@ -5,23 +5,107 @@ import ( "testing" "time" + "github.com/coder/envbuilder/log" "github.com/coder/envbuilder/log/hijack" "github.com/sirupsen/logrus" "github.com/stretchr/testify/require" ) -func TestLogrus(t *testing.T) { +func TestLogrus_Info(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Second) t.Cleanup(cancel) - messages := make(chan *logrus.Entry, 1) - hijack.Logrus(func(entry *logrus.Entry) { + 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 - }) - logrus.Infof("Testing!") + } + + 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!") + // We should receive the below. + logrus.Info("Testing!") + logrus.Warn("Warning!") + 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(): - require.FailNow(t, "timed out") - case message := <-messages: - require.Equal(t, "Testing!", message.Message) + t.Fatal("timeout") + case v = <-ch: } + return v } From 72791a486c3968eafa626ee20a8a6cf4608bf87e Mon Sep 17 00:00:00 2001 From: Cian Johnston Date: Tue, 27 Aug 2024 13:37:17 +0100 Subject: [PATCH 3/4] fixup! fix(log/hijack): properly set logrus level --- log/hijack/logrus_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log/hijack/logrus_test.go b/log/hijack/logrus_test.go index 44b32511..b2c841b0 100644 --- a/log/hijack/logrus_test.go +++ b/log/hijack/logrus_test.go @@ -90,9 +90,9 @@ func TestLogrus_Error(t *testing.T) { // The following should be filtered out. logrus.Trace("Tracing!") logrus.Debug("Debugging!") - // We should receive the below. logrus.Info("Testing!") logrus.Warn("Warning!") + // We should receive the below. logrus.Error("Error!") }() From 89df5443c1ff63926202e321306e74a574cfff7e Mon Sep 17 00:00:00 2001 From: Cian Johnston Date: Tue, 27 Aug 2024 14:42:27 +0100 Subject: [PATCH 4/4] move to package log --- envbuilder.go | 9 ++++----- log/{hijack => }/logrus.go | 33 ++++++++++++++++----------------- log/{hijack => }/logrus_test.go | 15 +++++++-------- 3 files changed, 27 insertions(+), 30 deletions(-) rename log/{hijack => }/logrus.go (60%) rename log/{hijack => }/logrus_test.go (89%) diff --git a/envbuilder.go b/envbuilder.go index d68d0a8d..7f3c983a 100644 --- a/envbuilder.go +++ b/envbuilder.go @@ -27,7 +27,6 @@ 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" @@ -283,9 +282,9 @@ func Run(ctx context.Context, opts options.Options) error { if opts.Verbose { lvl = log.LevelDebug } - hijack.Logrus(lvl, func(entry *logrus.Entry) { + log.HijackLogrus(lvl, func(entry *logrus.Entry) { for _, line := range strings.Split(entry.Message, "\r") { - opts.Logger(hijack.LogLevel(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line)) + opts.Logger(log.FromLogrus(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line)) } }) @@ -1059,9 +1058,9 @@ func RunCacheProbe(ctx context.Context, opts options.Options) (v1.Image, error) if opts.Verbose { lvl = log.LevelDebug } - hijack.Logrus(lvl, func(entry *logrus.Entry) { + log.HijackLogrus(lvl, func(entry *logrus.Entry) { for _, line := range strings.Split(entry.Message, "\r") { - opts.Logger(hijack.LogLevel(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line)) + opts.Logger(log.FromLogrus(entry.Level), "#%d: %s", stageNumber, color.HiBlackString(line)) } }) diff --git a/log/hijack/logrus.go b/log/logrus.go similarity index 60% rename from log/hijack/logrus.go rename to log/logrus.go index 1d59932b..3d70b114 100644 --- a/log/hijack/logrus.go +++ b/log/logrus.go @@ -1,18 +1,17 @@ -package hijack +package log import ( "io" - "github.com/coder/envbuilder/log" "github.com/sirupsen/logrus" ) -// Logrus hijacks the logrus logger and calls the callback for each log entry. +// 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 Logrus(lvl log.Level, callback func(entry *logrus.Entry)) { +func HijackLogrus(lvl Level, callback func(entry *logrus.Entry)) { logrus.StandardLogger().SetOutput(io.Discard) - logrus.StandardLogger().SetLevel(LogrusLevel(lvl)) + logrus.StandardLogger().SetLevel(ToLogrus(lvl)) logrus.StandardLogger().SetFormatter(&logrusFormatter{ callback: callback, empty: []byte{}, @@ -29,34 +28,34 @@ func (f *logrusFormatter) Format(entry *logrus.Entry) ([]byte, error) { return f.empty, nil } -func LogrusLevel(lvl log.Level) logrus.Level { +func ToLogrus(lvl Level) logrus.Level { switch lvl { - case log.LevelTrace: + case LevelTrace: return logrus.TraceLevel - case log.LevelDebug: + case LevelDebug: return logrus.DebugLevel - case log.LevelInfo: + case LevelInfo: return logrus.InfoLevel - case log.LevelWarn: + case LevelWarn: return logrus.WarnLevel - case log.LevelError: + case LevelError: return logrus.ErrorLevel default: return logrus.InfoLevel } } -func LogLevel(lvl logrus.Level) log.Level { +func FromLogrus(lvl logrus.Level) Level { switch lvl { case logrus.TraceLevel: - return log.LevelTrace + return LevelTrace case logrus.DebugLevel: - return log.LevelDebug + return LevelDebug case logrus.InfoLevel: - return log.LevelInfo + return LevelInfo case logrus.WarnLevel: - return log.LevelWarn + return LevelWarn default: // Error, Fatal, Panic - return log.LevelError + return LevelError } } diff --git a/log/hijack/logrus_test.go b/log/logrus_test.go similarity index 89% rename from log/hijack/logrus_test.go rename to log/logrus_test.go index b2c841b0..7b606696 100644 --- a/log/hijack/logrus_test.go +++ b/log/logrus_test.go @@ -1,4 +1,4 @@ -package hijack_test +package log_test import ( "context" @@ -6,12 +6,11 @@ import ( "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) { +func TestHijackLogrus_Info(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Second) t.Cleanup(cancel) messages := make(chan *logrus.Entry) @@ -21,7 +20,7 @@ func TestLogrus_Info(t *testing.T) { messages <- entry } - hijack.Logrus(log.LevelInfo, logf) + log.HijackLogrus(log.LevelInfo, logf) done := make(chan struct{}) go func() { @@ -41,7 +40,7 @@ func TestLogrus_Info(t *testing.T) { <-done } -func TestLogrus_Debug(t *testing.T) { +func TestHijackLogrus_Debug(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Second) t.Cleanup(cancel) messages := make(chan *logrus.Entry) @@ -51,7 +50,7 @@ func TestLogrus_Debug(t *testing.T) { messages <- entry } - hijack.Logrus(log.LevelDebug, logf) + log.HijackLogrus(log.LevelDebug, logf) done := make(chan struct{}) go func() { @@ -72,7 +71,7 @@ func TestLogrus_Debug(t *testing.T) { <-done } -func TestLogrus_Error(t *testing.T) { +func TestHijackLogrus_Error(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Second) t.Cleanup(cancel) messages := make(chan *logrus.Entry) @@ -82,7 +81,7 @@ func TestLogrus_Error(t *testing.T) { messages <- entry } - hijack.Logrus(log.LevelError, logf) + log.HijackLogrus(log.LevelError, logf) done := make(chan struct{}) go func() {