Make the debug-log command more useful

The debug-log command now supports log level filtering and attribute
filtering. The log level filtering will only be able to set the minimum
log level as low as the server is configured to stream. If the server has
its log level set as INFO, then setting the log level in the CLI to DEBUG
will have no effect.

But anything above what the server sends, is within the control of the client
to filter. This is all done client side.

Attribute filters are useful if you need to watch the logs for a particular
worker, entity, etc.

Signed-off-by: Gabriel Adrian Samfira <gsamfira@cloudbasesolutions.com>

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{
+	handlers := []slog.Handler{
-		Handler: han,
+		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 {
+var _ slog.Handler = &SlogMultiHandler{}
-	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)
-}
 
 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")
+	}
 }
 
 // clientReader waits for options changes from the client. The client can at any time