diff --git a/pkg/devcontainer/sshtunnel/sshtunnel.go b/pkg/devcontainer/sshtunnel/sshtunnel.go index 4c1acba8e..0ef6f17f9 100644 --- a/pkg/devcontainer/sshtunnel/sshtunnel.go +++ b/pkg/devcontainer/sshtunnel/sshtunnel.go @@ -3,6 +3,7 @@ package sshtunnel import ( "bufio" "context" + "encoding/json" "errors" "fmt" "io" @@ -471,6 +472,19 @@ func (l *TunnelLogStreamer) process(r io.Reader) { } } +type jsonLogLine struct { + Message string `json:"message,omitempty"` + Msg string `json:"msg,omitempty"` + Level string `json:"level,omitempty"` +} + +func (j *jsonLogLine) text() string { + if j.Message != "" { + return j.Message + } + return j.Msg +} + func (l *TunnelLogStreamer) logLine(line string) { line = strings.TrimSpace(line) // Remove carriage returns to prevent terminal overwriting (e.g. git progress) @@ -479,6 +493,13 @@ func (l *TunnelLogStreamer) logLine(line string) { return } + var obj jsonLogLine + if json.Unmarshal([]byte(line), &obj) == nil && obj.text() != "" { + level := normalizeLevel(obj.Level) + logAtLevel(level, obj.text()) + return + } + if matched, level := extractLogLevel(line); matched { logAtLevel(level, line) } else { @@ -486,6 +507,29 @@ func (l *TunnelLogStreamer) logLine(line string) { } } +const ( + levelDebug = "debug" + levelInfo = "info" + levelWarn = "warn" + levelError = "error" + levelFatal = "fatal" +) + +func normalizeLevel(raw string) string { + switch strings.ToLower(raw) { + case "trace", levelDebug: + return levelDebug + case levelInfo: + return levelInfo + case "warning", levelWarn: + return levelWarn + case levelError, "panic", levelFatal: + return levelError + default: + return levelDebug + } +} + func extractLogLevel(line string) (bool, string) { parts := strings.SplitN(line, " ", 3) if len(parts) < 2 || !strings.Contains(parts[0], ":") { @@ -494,7 +538,7 @@ func extractLogLevel(line string) (bool, string) { level := strings.ToLower(parts[1]) switch level { - case "debug", "info", "warn", "error", "fatal": + case levelDebug, levelInfo, levelWarn, levelError, levelFatal: return true, level default: return false, "" @@ -503,15 +547,15 @@ func extractLogLevel(line string) (bool, string) { func logAtLevel(level, msg string) { switch level { - case "debug": + case levelDebug: log.Debug(msg) - case "info": + case levelInfo: log.Info(msg) - case "warn": + case levelWarn: log.Warn(msg) - case "error": + case levelError: log.Error(msg) - case "fatal": + case levelFatal: log.Error(msg) default: log.Debug(msg) diff --git a/pkg/devcontainer/sshtunnel/sshtunnel_test.go b/pkg/devcontainer/sshtunnel/sshtunnel_test.go new file mode 100644 index 000000000..3c266be78 --- /dev/null +++ b/pkg/devcontainer/sshtunnel/sshtunnel_test.go @@ -0,0 +1,206 @@ +package sshtunnel + +import ( + "testing" + + "github.com/devsy-org/devsy/pkg/log" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap/zapcore" +) + +func TestLogLine_JSONPassthrough(t *testing.T) { + tests := []struct { + name string + input string + wantMsg string + wantLevel zapcore.Level + }{ + { + name: "json with message field", + input: `{"level":"info","message":"agent started"}`, + wantMsg: "agent started", + wantLevel: zapcore.InfoLevel, + }, + { + name: "json with msg field", + input: `{"level":"warn","msg":"disk nearly full"}`, + wantMsg: "disk nearly full", + wantLevel: zapcore.WarnLevel, + }, + { + name: "json error level", + input: `{"level":"error","message":"connection lost"}`, + wantMsg: "connection lost", + wantLevel: zapcore.ErrorLevel, + }, + { + name: "json debug level", + input: `{"level":"debug","message":"heartbeat sent"}`, + wantMsg: "heartbeat sent", + wantLevel: zapcore.DebugLevel, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + logs := log.InitTestObserved(t, zapcore.DebugLevel) + streamer := &TunnelLogStreamer{} + streamer.logLine(tt.input) + + entries := logs.All() + require.Len(t, entries, 1) + assert.Equal(t, tt.wantMsg, entries[0].Message) + assert.Equal(t, tt.wantLevel, entries[0].Level) + }) + } +} + +func TestLogLine_JSONLevelNormalization(t *testing.T) { + tests := []struct { + name string + input string + wantMsg string + wantLevel zapcore.Level + }{ + { + name: "trace maps to debug", + input: `{"level":"trace","message":"trace event"}`, + wantMsg: "trace event", + wantLevel: zapcore.DebugLevel, + }, + { + name: "warning maps to warn", + input: `{"level":"warning","message":"deprecated call"}`, + wantMsg: "deprecated call", + wantLevel: zapcore.WarnLevel, + }, + { + name: "fatal maps to error", + input: `{"level":"fatal","message":"panic recovered"}`, + wantMsg: "panic recovered", + wantLevel: zapcore.ErrorLevel, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + logs := log.InitTestObserved(t, zapcore.DebugLevel) + streamer := &TunnelLogStreamer{} + streamer.logLine(tt.input) + + entries := logs.All() + require.Len(t, entries, 1) + assert.Equal(t, tt.wantMsg, entries[0].Message) + assert.Equal(t, tt.wantLevel, entries[0].Level) + }) + } +} + +func TestLogLine_PlainText(t *testing.T) { + tests := []struct { + name string + input string + wantMsg string + wantLevel zapcore.Level + }{ + { + name: "timestamped text with level", + input: "2024-01-01T00:00:00Z info some message here", + wantMsg: "2024-01-01T00:00:00Z info some message here", + wantLevel: zapcore.InfoLevel, + }, + { + name: "plain text without level falls back to debug", + input: "just a plain line", + wantMsg: "just a plain line", + wantLevel: zapcore.DebugLevel, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + logs := log.InitTestObserved(t, zapcore.DebugLevel) + streamer := &TunnelLogStreamer{} + streamer.logLine(tt.input) + + entries := logs.All() + require.Len(t, entries, 1) + assert.Equal(t, tt.wantMsg, entries[0].Message) + assert.Equal(t, tt.wantLevel, entries[0].Level) + }) + } +} + +func TestLogLine_EmptyAndWhitespace(t *testing.T) { + logs := log.InitTestObserved(t, zapcore.DebugLevel) + streamer := &TunnelLogStreamer{} + + streamer.logLine("") + streamer.logLine(" ") + streamer.logLine("\r\n") + + assert.Empty(t, logs.All()) +} + +func TestLogLine_JSONWithoutMessage(t *testing.T) { + logs := log.InitTestObserved(t, zapcore.DebugLevel) + streamer := &TunnelLogStreamer{} + + streamer.logLine(`{"level":"info","key":"value"}`) + + entries := logs.All() + require.Len(t, entries, 1) + assert.Equal(t, zapcore.DebugLevel, entries[0].Level) +} + +func TestExtractLogLevel(t *testing.T) { + tests := []struct { + input string + wantMatch bool + wantLevel string + }{ + {"2024-01-01T00:00:00Z debug foo", true, "debug"}, + {"2024-01-01T00:00:00Z info bar", true, "info"}, + {"2024-01-01T00:00:00Z warn baz", true, "warn"}, + {"2024-01-01T00:00:00Z error qux", true, "error"}, + {"2024-01-01T00:00:00Z fatal crash", true, "fatal"}, + {"no-colon info msg", false, ""}, + {"plain text", false, ""}, + {"ts: unknown msg", false, ""}, + } + + for _, tt := range tests { + t.Run(tt.input, func(t *testing.T) { + matched, level := extractLogLevel(tt.input) + assert.Equal(t, tt.wantMatch, matched) + assert.Equal(t, tt.wantLevel, level) + }) + } +} + +func TestNormalizeLevel(t *testing.T) { + tests := []struct { + input string + want string + }{ + {"trace", "debug"}, + {"DEBUG", "debug"}, + {"info", "info"}, + {"INFO", "info"}, + {"warning", "warn"}, + {"warn", "warn"}, + {"WARN", "warn"}, + {"error", "error"}, + {"panic", "error"}, + {"fatal", "error"}, + {"unknown", "debug"}, + {"", "debug"}, + } + + for _, tt := range tests { + t.Run(tt.input, func(t *testing.T) { + assert.Equal(t, tt.want, normalizeLevel(tt.input)) + }) + } +}