fix(tunnel): extract JSON log lines instead of double-wrapping

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,13 +493,43 @@ 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 {
 		log.Debug(line)
 	}
 }
 
+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)

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