Go Slog: Eigener Log Handler für bessere Lesbarkeit im Terminal

Slog Output mit Libgloss

Seit Go 1.21 ist das strukturierte Logging mit slog Teil der Standardbibliothek. Die standardmäßigen Handler für JSON und Text sind in Serverlog Tools wie Prometheus oder Grafana Loki sehr nützlich, da sie strukturierte Daten liefern, die maschinell ausgewertet werden können. Bei der lokalen Entwicklung sind diese Ausgaben jedoch oft schwer zu lesen - besonders wenn viele Logs durchlaufen und man schnell die wichtigen Informationen erfassen möchte.

Mit einem eigenen Handler können wir das Beste aus beiden Welten kombinieren: Farbige, gut lesbare Logs für die lokale Entwicklung und strukturierte JSON-Logs für Produktion. Der Wechsel zwischen beiden Modi erfolgt dabei transparent über die Handler-Auswahl. Zusätzlich ist es möglich, weitere Logik zu implementieren, die bestimmte Felder oder ganze Nachrichten lokal filtert.

Der folgende Code ist entstanden, um schnell lokal bessere Logs zu erhalten. Daher wurde nicht besonders viel Wert auf Performance oder Clean Code gelegt. Er musste schnell entstehen und funktioniert für meine Zwecke.

Handler Interface

Ein Slog Handler Interface ist nicht besonders kompliziert.

type Handler interface {
    Enabled(context.Context, Level) bool
    Handle(context.Context, Record) error
    WithAttrs(attrs []Attr) Handler
    WithGroup(name string) Handler
}

Die Enabled Methode entscheidet, ob der Log Eintrag für das Level verarbeitet werden soll. Handle schreibt die eigentliche Nachricht und formatiert diese. Die Methoden WithAttrs und WithGroup verarbeitet die Slog Attribute die z.B. mit slog.With(slog.String("key", "value")) hinzugefügt werden können.

Glossy Handler

Um die Logs schöner zu rendern, erstelle ich mir einen eigenen Handler, der die Nachrichten mit libgloss formatiert. Lipgloss ist eine Bibliothek, die es ermöglicht, Terminal-Ausgaben mit Farben und Stilen zu versehen.

type GlossyHandler struct {
    out io.Writer
    mu  *sync.Mutex

    minLevel slog.Level

    // Pre-computed attributes from WithAttrs calls
    attrs []slog.Attr

    // Current active groups from WithGroup calls
    groups []string
}

// Enabled checks if the handler is enabled for the given log level.
func (h *GlossyHandler) Enabled(ctx context.Context, level slog.Level) bool {
	return level >= h.minLevel
}

// NewGlossyHandler creates a new GlossyHandler with the specified output writer and minimum log level.
func NewGlossyHandler(out io.Writer, minLevel slog.Level) *GlossyHandler {
	return &GlossyHandler{
		out:      out,
		mu:       &sync.Mutex{},
		minLevel: minLevel,
	}
}

Ein Mutex wird verwendet, um die Attribute und Gruppen threadsafe zu ändern. Die Farben können einfach über lipgloss Styles definiert werden. Jedes Log-Level bekommt eine eigene Farbe zugewiesen - Grau für Debug, Blau für Info, Orange für Warnings und Rot für Errors.

var levelStyles = map[slog.Level]lipgloss.Style{
    slog.LevelDebug: lipgloss.NewStyle().Foreground(lipgloss.Color("8")).Bold(true),
    slog.LevelInfo:  lipgloss.NewStyle().Foreground(lipgloss.Color("12")).Bold(true),
    slog.LevelWarn:  lipgloss.NewStyle().Foreground(lipgloss.Color("208")).Bold(true),
    slog.LevelError: lipgloss.NewStyle().Foreground(lipgloss.Color("196")).Bold(true),
}

Zusätzlich definiere ich Labels für die Log-Level, die später in der Ausgabe verwendet werden.

// levelAbbreviations provides shorter forms of level names
var levelAbbreviations = map[slog.Level]string{
	slog.LevelDebug: "[DEBUG]",
	slog.LevelInfo:  "[INFO] ",
	slog.LevelWarn:  "[WARN] ",
	slog.LevelError: "[ERROR]",
}

Strukturierte Log-Ausgabe

Die Handle Methode formatiert jeden Log-Eintrag in eine gut lesbare Zeile mit farbigen Komponenten. Um schneller die Zugehörigkeit einer Log Nachricht zu erkennen, verwende ich in meinen Projekten gerne die Attribute component und context. Jedes Modul setzt in component einen Identifier. Ein Beispiel könnte api für einen HTTP Server oder handler.eventName für einen Event Handler sein. Das Feld context nutze ich etwas flexibler. Es kann der aktuelle Nutzer oder Dokument ID sein. Im Fall von HTTP Servern kann es auch der API Handler Name sein.

[INFO] [api] [createUser] User created {"userID": "1", "userName": "Gopher"}

Als erstes wird im Handler geprüft, ob der Log-Eintrag für das aktuelle Level aktiviert ist. Wenn nicht, wird die Methode einfach beendet. Anschließend wird der Mutex gesperrt, um mit den Attributen und Gruppen zu arbeiten. Eine mögliche Verbesserung wäre, den Mutex nur zu sperren, wenn einmal kurz die Attribute und Gruppen gelesen werden.

Als ersten Output suchen wir den Style und den Text für das Level und schreiben dies in den String Builder.

func (h *GlossyHandler) Handle(ctx context.Context, record slog.Record) error {
    if !h.Enabled(ctx, record.Level) {
        return nil
    }

    h.mu.Lock()
    defer h.mu.Unlock()

    var builder strings.Builder

    levelStyle := levelStyles[record.Level]
    levelName := levelAbbreviations[record.Level]

    // Format the log message
    builder.WriteString(levelStyle.Render(levelName))
    builder.WriteString(" ")

    // ToDo: Handle message formatting

    // Add a newline
    builder.WriteString("\n")

    // Write the formatted message to the output
    _, err := io.WriteString(h.out, builder.String())
    return err
}

Im Anschluss müssen wir das Component und Context Value finden und wenn es existiert, mit dem jeweiligen Style in den String Builder schreiben.

func (h *GlossyHandler) Handle(ctx context.Context, record slog.Record) error {
    // ... (vorheriger Code)

    // Component
    componentValue := ""
    contextValue := ""

    record.Attrs(func(a slog.Attr) bool {
        if a.Key == "component" {
            componentValue = a.Value.String()
        } else if a.Key == "context" {
            contextValue = a.Value.String()
        }
        if componentValue != "" && contextValue != "" {
            return false
        }

        return true
    })

    if componentValue == "" {
        for _, attr := range h.attrs {
            if attr.Key == "component" {
                componentValue = attr.Value.String()
            } else if attr.Key == "context" {
                contextValue = attr.Value.String()
            }
            if componentValue != "" && contextValue != "" {
                break
            }
        }
    }

    if componentValue != "" {
        componentStyle := lipgloss.NewStyle().Foreground(lipgloss.Color("5"))
        componentFormatted := componentStyle.Render(fmt.Sprintf("[%s]", componentValue))
        builder.WriteString(componentFormatted)
        builder.WriteString(" ")
    }

    if contextValue != "" {
        contextStyle := lipgloss.NewStyle().Foreground(lipgloss.Color("20"))
        contextFormatted := contextStyle.Render(fmt.Sprintf("[%s]", contextValue))
        builder.WriteString(contextFormatted)
        builder.WriteString(" ")
    }

    // ... (vorheriger Code)
}

Zum Abschluss müssen wir die eigentliche Nachricht formatieren und alle restlichen Attribute als JSON hinzufügen.

func (h *GlossyHandler) Handle(ctx context.Context, record slog.Record) error {
    // ... (vorheriger Code)

    // Format the message
    messageStyle := lipgloss.NewStyle().Foreground(lipgloss.Color("15"))
    message := messageStyle.Render(record.Message)
    builder.WriteString(message)

    // Process all attributes (except "component" which was already handled)
    attrMap := make(map[string]any)

    // First add our pre-computed attributes
    for _, attr := range h.attrs {
        if attr.Key != "component" && attr.Key != "context" {
            attrMap[attr.Key] = attr.Value.Any()
        }
    }

    // Then add record attributes (possibly overriding pre-computed ones)
    record.Attrs(func(attr slog.Attr) bool {
        if attr.Key != "component" && attr.Key != "context" && attr.Key != slog.TimeKey && attr.Key != slog.LevelKey && attr.Key != slog.MessageKey {
            attrMap[attr.Key] = attr.Value.Any()
        }
        return true
    })

    // Add attributes if there are any
    if len(attrMap) > 0 {
        builder.WriteString(" ")

        // Format attributes in a subtle style
        attrStyle := lipgloss.NewStyle().Foreground(lipgloss.Color("246"))

        attrJson, err := json.Marshal(attrMap)
        if err != nil {
            attrJson = []byte("{}")
        }

        builder.WriteString(attrStyle.Render(string(attrJson)))
    }

    // ... (vorheriger Code)
}

Attribute und Gruppen

Bei Aufrufen von slog.With wird eine neue Instanz des Handlers erstellt. Mit den alten und neuen Attributen muss eine neue Instanz des Handlers erstellt werden. Um nicht die alte Instanz zu verändern, müssen die Slices für attrs und groups kopiert werden. So kann der Log Handler immer weiter übergeben werden, ohne z.B. die Logausgabe in anderen HTTP Handlern zu beeinflussen.

func (h *GlossyHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	// Create a new handler with the same properties
	newHandler := &GlossyHandler{
		out:      h.out,
		mu:       h.mu, // Share the mutex to ensure serialized output
		minLevel: h.minLevel,
		groups:   slices.Clone(h.groups),
	}

	// Prepare a map to store existing attributes with their keys for quick lookup
	existingAttrs := make(map[string]int, len(h.attrs))
	for i, attr := range h.attrs {
		existingAttrs[attr.Key] = i
	}

	// Copy existing attrs
	newHandler.attrs = make([]slog.Attr, len(h.attrs))
	copy(newHandler.attrs, h.attrs)

	// Apply any active groups to the new attributes
	prefix := ""
	if len(h.groups) > 0 {
		prefix = strings.Join(h.groups, ".")
	}

	// Add or override the new attributes
	for _, attr := range attrs {
		fullKey := attr.Key
		if prefix != "" {
			fullKey = prefix + "." + attr.Key
		}

		// Check if this attribute already exists
		if idx, exists := existingAttrs[fullKey]; exists {
			// Override existing attribute
			newHandler.attrs[idx] = slog.Attr{Key: fullKey, Value: attr.Value}
		} else {
			// Add new attribute
			newHandler.attrs = append(newHandler.attrs, slog.Attr{Key: fullKey, Value: attr.Value})
		}
	}

	return newHandler
}

Ich selbst nutze das Gruppen Feature von Slog nicht, daher ist die Implementierung hier sehr einfach gehalten und deckt wahrscheinlich nicht alles ab.


func (h *GlossyHandler) WithGroup(name string) slog.Handler {
	if name == "" {
		return h
	}

	// Create a new handler with the same properties
	newHandler := &GlossyHandler{
		out:      h.out,
		mu:       h.mu, // Share the mutex to ensure serialized output
		minLevel: h.minLevel,
		attrs:    slices.Clone(h.attrs),
	}

	// Add the new group to the groups slice
	newGroups := make([]string, 0, len(h.groups)+1)
	newGroups = append(newGroups, h.groups...)
	newGroups = append(newGroups, name)
	newHandler.groups = newGroups

	return newHandler
}

Verwendung

Der Handler ist sehr einfach zu verwenden. Um zwischen dem JSON und dem Glossy Handler zu wechseln, kann z.B. einfach auf eine Umgebungsvariable geprüft werden.

func main() {
    var handler slog.Handler
    
    if os.Getenv("ENV") == "production" {
        // JSON handler for production
        handler = slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
            Level: slog.LevelInfo,
        })
    } else {
        // Glossy handler for development
        handler = NewGlossyHandler(os.Stdout, slog.LevelDebug)
    }
    
    log := slog.New(handler)
    log.Info("Starting", slog.String("component", "main"))
}

Der Glossy Handler ist für die lokale Entwicklung gedacht, wo kein JSON Parser die Logs aufbereitet und Farben sichtbar sind. Die Performance wird im Vergleich zum JSON Handler wahrscheinlich schlechter sein.

In der Handle Methode kann relative einfach weitere Logik implementiert werden, um z.B. bestimmte Nachrichten zu filtern oder zu formatieren.

Slog Handler für bessere Lesbarkeit in lokalen Logs

Handler Interface

Glossy Handler

Strukturierte Log-Ausgabe

Attribute und Gruppen

Verwendung

Weitere Links

Handler Interface#

Glossy Handler#

Strukturierte Log-Ausgabe#

Attribute und Gruppen#

Verwendung#

Weitere Links#

Handler Interface

Glossy Handler

Strukturierte Log-Ausgabe

Attribute und Gruppen

Verwendung

Weitere Links