Merge pull request #499 from gabriel-samfira/better-cli-log-formatting

Make the debug-log command more useful

apiserver/controllers/controllers.go

@@ -30,7 +30,6 @@ import (
 
 	gErrors "github.com/cloudbase/garm-provider-common/errors"
 	"github.com/cloudbase/garm-provider-common/util"
-	"github.com/cloudbase/garm/apiserver/events"
 	"github.com/cloudbase/garm/apiserver/params"
 	"github.com/cloudbase/garm/auth"
 	"github.com/cloudbase/garm/config"
@@ -39,6 +38,7 @@ import (
 	"github.com/cloudbase/garm/runner" //nolint:typecheck
 	garmUtil "github.com/cloudbase/garm/util"
 	wsWriter "github.com/cloudbase/garm/websocket"
+	"github.com/cloudbase/garm/workers/websocket/events"
 )
 
 func NewAPIController(r *runner.Runner, authenticator *auth.Authenticator, hub *wsWriter.Hub, apiCfg config.APIServer) (*APIController, error) {

cmd/garm-cli/cmd/log.go

@@ -16,6 +16,7 @@ package cmd
 import (
 	"context"
 	"os/signal"
+	"strings"
 
 	"github.com/spf13/cobra"
 
@@ -23,7 +24,12 @@ import (
 	"github.com/cloudbase/garm/cmd/garm-cli/common"
 )
 
-var eventsFilters string
+var (
+	eventsFilters string
+	logLevel      string
+	filters       []string
+	enableColor   bool
+)
 
 var logCmd = &cobra.Command{
 	Use:          "debug-log",
@@ -34,7 +40,19 @@ var logCmd = &cobra.Command{
 		ctx, stop := signal.NotifyContext(context.Background(), signals...)
 		defer stop()
 
-		reader, err := garmWs.NewReader(ctx, mgr.BaseURL, "/api/v1/ws/logs", mgr.Token, common.PrintWebsocketMessage)
+		// Parse filters into map
+		attributeFilters := make(map[string]string)
+		for _, filter := range filters {
+			parts := strings.SplitN(filter, "=", 2)
+			if len(parts) == 2 {
+				attributeFilters[parts[0]] = parts[1]
+			}
+		}
+
+		// Create log formatter with filters
+		logFormatter := common.NewLogFormatter(logLevel, attributeFilters, enableColor)
+
+		reader, err := garmWs.NewReader(ctx, mgr.BaseURL, "/api/v1/ws/logs", mgr.Token, logFormatter.FormatWebsocketMessage)
 		if err != nil {
 			return err
 		}
@@ -49,5 +67,9 @@ var logCmd = &cobra.Command{
 }
 
 func init() {
+	logCmd.Flags().StringVar(&logLevel, "log-level", "", "Minimum log level to display (DEBUG, INFO, WARN, ERROR)")
+	logCmd.Flags().StringArrayVar(&filters, "filter", []string{}, "Filter logs by attribute (format: key=value) or message content (msg=text). You can specify this option multiple times. The filter will return true for any of the attributes you set.")
+	logCmd.Flags().BoolVar(&enableColor, "enable-color", true, "Enable color logging (auto-detects terminal support)")
+
 	rootCmd.AddCommand(logCmd)
 }

cmd/garm-cli/common/common.go

@@ -15,8 +15,14 @@
 package common
 
 import (
+	"encoding/json"
 	"errors"
 	"fmt"
+	"os"
+	"runtime"
+	"sort"
+	"strings"
+	"time"
 
 	"github.com/manifoldco/promptui"
 	"github.com/nbutton23/zxcvbn-go"
@@ -74,3 +80,246 @@ func PrintWebsocketMessage(_ int, msg []byte) error {
 	fmt.Println(util.SanitizeLogEntry(string(msg)))
 	return nil
 }
+
+type LogFormatter struct {
+	MinLevel         string
+	AttributeFilters map[string]string
+	EnableColor      bool
+}
+
+type LogRecord struct {
+	Time  string                 `json:"time"`
+	Level string                 `json:"level"`
+	Msg   string                 `json:"msg"`
+	Attrs map[string]interface{} `json:",inline"`
+}
+
+// Color codes for different log levels
+const (
+	ColorReset   = "\033[0m"
+	ColorRed     = "\033[31m"
+	ColorYellow  = "\033[33m"
+	ColorBlue    = "\033[34m"
+	ColorMagenta = "\033[35m"
+	ColorCyan    = "\033[36m"
+	ColorWhite   = "\033[37m"
+	ColorGray    = "\033[90m"
+)
+
+func (lf *LogFormatter) colorizeLevel(level string) string {
+	if !lf.EnableColor {
+		return level
+	}
+
+	levelUpper := strings.TrimSpace(strings.ToUpper(level))
+	switch levelUpper {
+	case "ERROR":
+		return ColorRed + level + ColorReset
+	case "WARN", "WARNING":
+		return ColorYellow + level + ColorReset
+	case "INFO":
+		return ColorBlue + level + ColorReset
+	case "DEBUG":
+		return ColorMagenta + level + ColorReset
+	default:
+		return level
+	}
+}
+
+func (lf *LogFormatter) shouldFilterLevel(level string) bool {
+	if lf.MinLevel == "" {
+		return false
+	}
+
+	levelMap := map[string]int{
+		"DEBUG": 0,
+		"INFO":  1,
+		"WARN":  2,
+		"ERROR": 3,
+	}
+
+	minLevelNum, exists := levelMap[strings.ToUpper(lf.MinLevel)]
+	if !exists {
+		return false
+	}
+
+	currentLevelNum, exists := levelMap[strings.ToUpper(level)]
+	if !exists {
+		return false
+	}
+
+	return currentLevelNum < minLevelNum
+}
+
+func (lf *LogFormatter) matchesAttributeFilters(attrs map[string]interface{}, msg string) bool {
+	if len(lf.AttributeFilters) == 0 {
+		return true
+	}
+
+	for key, expectedValue := range lf.AttributeFilters {
+		// Special handling for message filtering
+		if key == "msg" {
+			if strings.Contains(msg, expectedValue) {
+				return true
+			}
+		}
+
+		// Regular attribute filtering
+		actualValue, exists := attrs[key]
+		if exists {
+			actualStr := fmt.Sprintf("%v", actualValue)
+			if actualStr == expectedValue {
+				return true
+			}
+		}
+	}
+
+	return false
+}
+
+func (lf *LogFormatter) FormatWebsocketMessage(_ int, msg []byte) error {
+	// Try to parse as JSON log record
+	var logRecord LogRecord
+	err := json.Unmarshal(msg, &logRecord)
+	if err != nil {
+		// If it's not JSON, print as-is (sanitized)
+		_, err = fmt.Println(util.SanitizeLogEntry(string(msg)))
+		return err
+	}
+
+	// Apply level filtering
+	if lf.shouldFilterLevel(logRecord.Level) {
+		return nil
+	}
+
+	// Parse additional attributes from the JSON
+	var fullRecord map[string]interface{}
+	if err := json.Unmarshal(msg, &fullRecord); err == nil {
+		// Remove standard fields and keep only attributes
+		delete(fullRecord, "time")
+		delete(fullRecord, "level")
+		delete(fullRecord, "msg")
+		logRecord.Attrs = fullRecord
+	}
+
+	// Apply attribute filtering
+	if !lf.matchesAttributeFilters(logRecord.Attrs, logRecord.Msg) {
+		return nil
+	}
+
+	// Format timestamp to fixed width
+	timeStr := logRecord.Time
+	if t, err := time.Parse(time.RFC3339Nano, logRecord.Time); err == nil {
+		timeStr = t.Format("2006-01-02 15:04:05.000")
+	}
+
+	// Format log level to fixed width (5 characters)
+	levelStr := lf.colorizeLevel(fmt.Sprintf("%-5s", strings.ToUpper(logRecord.Level)))
+
+	// Highlight message if it matches a msg filter
+	msgStr := logRecord.Msg
+	if msgFilter, hasMsgFilter := lf.AttributeFilters["msg"]; hasMsgFilter {
+		if strings.Contains(msgStr, msgFilter) && lf.EnableColor {
+			msgStr = ColorYellow + msgStr + ColorReset
+		}
+	}
+
+	output := fmt.Sprintf("%s [%s] %s", timeStr, levelStr, msgStr)
+
+	// Add attributes if any
+	if len(logRecord.Attrs) > 0 {
+		// Get sorted keys for consistent output
+		var keys []string
+		for k := range logRecord.Attrs {
+			keys = append(keys, k)
+		}
+		sort.Strings(keys)
+
+		var attrPairs []string
+		for _, k := range keys {
+			v := logRecord.Attrs[k]
+			attrStr := fmt.Sprintf("%s=%v", k, v)
+
+			// Highlight filtered attributes
+			if filterValue, isFiltered := lf.AttributeFilters[k]; isFiltered && fmt.Sprintf("%v", v) == filterValue {
+				if lf.EnableColor {
+					attrStr = ColorYellow + attrStr + ColorGray
+				}
+			} else if lf.EnableColor {
+				attrStr = ColorGray + attrStr
+			}
+
+			attrPairs = append(attrPairs, attrStr)
+		}
+		if len(attrPairs) > 0 {
+			if lf.EnableColor {
+				output += " " + strings.Join(attrPairs, " ") + ColorReset
+			} else {
+				output += " " + strings.Join(attrPairs, " ")
+			}
+		}
+	}
+
+	fmt.Println(output)
+	return nil
+}
+
+// supportsColor checks if the current terminal/environment supports ANSI colors.
+// This is best effort. There is no reliable way to determine if a terminal supports
+// color. Set NO_COLOR=1 to disable color if your terminal doesn't support it, but this
+// function returns true.
+func supportsColor() bool {
+	// Check NO_COLOR environment variable (universal standard)
+	if os.Getenv("NO_COLOR") != "" {
+		return false
+	}
+
+	// Check FORCE_COLOR environment variable
+	if os.Getenv("FORCE_COLOR") != "" {
+		return true
+	}
+
+	// On Windows, check for modern terminal support
+	if runtime.GOOS == "windows" {
+		// Check for Windows Terminal
+		if os.Getenv("WT_SESSION") != "" {
+			return true
+		}
+		// Check for ConEmu
+		if os.Getenv("ConEmuANSI") == "ON" {
+			return true
+		}
+		// Check for other modern terminals
+		term := os.Getenv("TERM")
+		if strings.Contains(term, "color") || term == "xterm-256color" || term == "screen-256color" {
+			return true
+		}
+		// Modern PowerShell and cmd.exe with VT processing
+		if os.Getenv("TERM_PROGRAM") != "" {
+			return true
+		}
+		// Default to false for older Windows cmd.exe
+		return false
+	}
+
+	// On Unix-like systems, check TERM
+	term := os.Getenv("TERM")
+	if term == "" || term == "dumb" {
+		return false
+	}
+
+	return true
+}
+
+func NewLogFormatter(minLevel string, attributeFilters map[string]string, color bool) *LogFormatter {
+	var enableColor bool
+	if color && supportsColor() {
+		enableColor = true
+	}
+
+	return &LogFormatter{
+		MinLevel:         minLevel,
+		AttributeFilters: attributeFilters,
+		EnableColor:      enableColor,
+	}
+}

cmd/garm/main.go

@@ -18,7 +18,6 @@ import (
 	"context"
 	"flag"
 	"fmt"
-	"io"
 	"log"
 	"log/slog"
 	"net"
@@ -104,16 +103,6 @@ func setupLogging(ctx context.Context, logCfg config.Logging, hub *websocket.Hub
 		}
 	}()
 
-	writers := []io.Writer{
-		logWriter,
-	}
-
-	if hub != nil {
-		writers = append(writers, hub)
-	}
-
-	wr := io.MultiWriter(writers...)
-
 	var logLevel slog.Level
 	switch logCfg.LogLevel {
 	case config.LevelDebug:
@@ -134,16 +123,25 @@ func setupLogging(ctx context.Context, logCfg config.Logging, hub *websocket.Hub
 		Level:     logLevel,
 	}
 
-	var han slog.Handler
+	var fileHan slog.Handler
 	switch logCfg.LogFormat {
 	case config.FormatJSON:
-		han = slog.NewJSONHandler(wr, &opts)
+		fileHan = slog.NewJSONHandler(logWriter, &opts)
 	default:
-		han = slog.NewTextHandler(wr, &opts)
+		fileHan = slog.NewTextHandler(logWriter, &opts)
 	}
 
-	wrapped := garmUtil.ContextHandler{
-		Handler: han,
+	handlers := []slog.Handler{
+		fileHan,
+	}
+
+	if hub != nil {
+		wsHan := slog.NewJSONHandler(hub, &opts)
+		handlers = append(handlers, wsHan)
+	}
+
+	wrapped := &garmUtil.SlogMultiHandler{
+		Handlers: handlers,
 	}
 	slog.SetDefault(slog.New(wrapped))
 }

util/logging.go

@@ -25,20 +25,58 @@ const (
 	slogCtxFields slogContextKey = "slog_ctx_fields"
 )
 
-type ContextHandler struct {
-	slog.Handler
-}
-
-func (h ContextHandler) Handle(ctx context.Context, r slog.Record) error {
-	attrs, ok := ctx.Value(slogCtxFields).([]slog.Attr)
-	if ok {
-		for _, v := range attrs {
-			r.AddAttrs(v)
-		}
-	}
-	return h.Handler.Handle(ctx, r)
-}
+var _ slog.Handler = &SlogMultiHandler{}
 
 func WithSlogContext(ctx context.Context, attrs ...slog.Attr) context.Context {
 	return context.WithValue(ctx, slogCtxFields, attrs)
 }
+
+type SlogMultiHandler struct {
+	Handlers []slog.Handler
+}
+
+func (m *SlogMultiHandler) Enabled(ctx context.Context, level slog.Level) bool {
+	// Enabled if any handler is enabled
+	for _, h := range m.Handlers {
+		if h.Enabled(ctx, level) {
+			return true
+		}
+	}
+	return false
+}
+
+func (m *SlogMultiHandler) Handle(ctx context.Context, r slog.Record) error {
+	record := r.Clone()
+	attrs, ok := ctx.Value(slogCtxFields).([]slog.Attr)
+	if ok {
+		for _, v := range attrs {
+			record.AddAttrs(v)
+		}
+	}
+
+	var firstErr error
+	for _, h := range m.Handlers {
+		if err := h.Handle(ctx, record); err != nil && firstErr == nil {
+			firstErr = err
+		}
+	}
+	return firstErr
+}
+
+func (m *SlogMultiHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	hs := make([]slog.Handler, len(m.Handlers))
+	for i, h := range m.Handlers {
+		hs[i] = h.WithAttrs(attrs)
+	}
+	return &SlogMultiHandler{
+		Handlers: hs,
+	}
+}
+
+func (m *SlogMultiHandler) WithGroup(name string) slog.Handler {
+	hs := make([]slog.Handler, len(m.Handlers))
+	for i, h := range m.Handlers {
+		hs[i] = h.WithGroup(name)
+	}
+	return &SlogMultiHandler{hs}
+}

websocket/client.go

@@ -143,20 +143,18 @@ func (c *Client) Write(msg []byte) (int, error) {
 	defer c.mux.Unlock()
 
 	if !c.running {
-		return 0, fmt.Errorf("client is stopped")
+		return 0, fmt.Errorf("websocket client is stopped")
 	}
 
 	tmp := make([]byte, len(msg))
 	copy(tmp, msg)
-	timer := time.NewTimer(5 * time.Second)
-	defer timer.Stop()
 
 	select {
-	case <-timer.C:
-		return 0, fmt.Errorf("timed out sending message to client")
 	case c.send <- tmp:
+		return len(tmp), nil
+	default:
+		return 0, fmt.Errorf("timed out sending message to websocket client")
 	}
-	return len(tmp), nil
 }
 
 // clientReader waits for options changes from the client. The client can at any time