Log-Format auf [INFO]/[WARN]/[ERROR]/[DEBUG]-Tags umgestellt, Logging erweitert

2026-03-29 21:44:25 +02:00
parent 58bb3b038e
commit 1e51010f10
8 changed files with 188 additions and 15 deletions
--- a/cmd/mcbdd/caldav.go
+++ b/cmd/mcbdd/caldav.go
@@ -23,6 +23,7 @@ const (
 // ihn nur, wenn alle enthaltenen Events die Daemon-PRODID tragen. Enthält der
 // Kalender fremde Events, wird er nicht gelöscht und eine Warnung geloggt.
 func (d *Daemon) cleanupOldCalendar(ctx context.Context, httpClient webdav.HTTPClient, user, oldName string) error {
+	slog.DebugContext(ctx, "checking for old calendar to clean up", "user", user, "oldName", oldName)
 	endpoint, err := url.JoinPath(d.baseURL, "SOGo/dav", user, "Calendar/")
 	if err != nil {
 		return err
@@ -35,6 +36,7 @@ func (d *Daemon) cleanupOldCalendar(ctx context.Context, httpClient webdav.HTTPC
 	if err != nil {
 		return err
 	}
+	slog.DebugContext(ctx, "found calendars", "user", user, "count", len(cc))
 	found := false
 	for _, c := range cc {
 		if strings.HasSuffix(c.Path, fmt.Sprintf("/%s", oldName)) {
@@ -43,8 +45,10 @@ func (d *Daemon) cleanupOldCalendar(ctx context.Context, httpClient webdav.HTTPC
 		}
 	}
 	if !found {
+		slog.DebugContext(ctx, "old calendar not found, nothing to clean up", "user", user, "oldName", oldName)
 		return nil
 	}
+	slog.DebugContext(ctx, "old calendar found, checking events", "user", user, "oldName", oldName)
 	calendarPath := fmt.Sprintf("/SOGo/dav/%s/Calendar/%s", user, oldName)
 	events, err := cl.QueryCalendar(ctx, calendarPath, &caldav.CalendarQuery{
 		CompRequest: caldav.CalendarCompRequest{
@@ -76,6 +80,7 @@ func (d *Daemon) cleanupOldCalendar(ctx context.Context, httpClient webdav.HTTPC
 }

 func (d *Daemon) ensureBirthdayCal(ctx context.Context, httpClient webdav.HTTPClient, user string) error {
+	slog.DebugContext(ctx, "ensuring birthday calendar exists", "user", user, "calendar", d.calendarName)
 	endpoint, err := url.JoinPath(d.baseURL, "SOGo/dav", user, "Calendar/")
 	if err != nil {
 		return err
@@ -90,13 +95,14 @@ func (d *Daemon) ensureBirthdayCal(ctx context.Context, httpClient webdav.HTTPCl
 	}
 	for _, c := range cc {
 		if strings.HasSuffix(c.Path, fmt.Sprintf("/%s", d.calendarName)) {
+			slog.DebugContext(ctx, "birthday calendar already exists", "user", user)
 			return nil
 		}
 	}
 	if err := cl.Mkdir(ctx, d.calendarName); err != nil {
 		return err
 	}
-	slog.InfoContext(ctx, "created birthday calendar", "user", user)
+	slog.InfoContext(ctx, "created birthday calendar", "user", user, "calendar", d.calendarName)
 	return nil
 }

@@ -167,6 +173,8 @@ func (d *Daemon) syncBirthdaysToCal(ctx context.Context, httpClient webdav.HTTPC
 	}
 	if (counterAdded + counterDelete) > 0 {
 		slog.InfoContext(ctx, "synchronized birthday events", "user", user, "added", counterAdded, "removed", counterDelete)
+	} else {
+		slog.DebugContext(ctx, "birthday events already in sync", "user", user, "total", len(bevs))
 	}
 	return nil
 }
--- a/cmd/mcbdd/carddav.go
+++ b/cmd/mcbdd/carddav.go
@@ -40,8 +40,10 @@ func (d *Daemon) getBirthdays(ctx context.Context, httpClient webdav.HTTPClient,
 	if err != nil {
 		return nil, err
 	}
+	slog.DebugContext(ctx, "found address books", "user", user, "count", len(bb))
 	contacts := make([]BirthdayContact, 0)
 	for _, b := range bb {
+		slog.DebugContext(ctx, "querying address book", "user", user, "path", b.Path)
 		oo, err := cl.QueryAddressBook(ctx, b.Path, &carddav.AddressBookQuery{})
 		if err != nil {
 			if err.Error() == "501 Not Implemented" {
--- a/cmd/mcbdd/health.go
+++ b/cmd/mcbdd/health.go
@@ -3,6 +3,7 @@ package main
 import (
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"os"
 	"path/filepath"
 	"sync"
@@ -57,7 +58,11 @@ func (h *healthState) update(err error) {
 		s.LastError = err.Error()
 	}
 	data, _ := json.Marshal(s)
-	os.WriteFile(h.filePath, data, 0644)
+	if writeErr := os.WriteFile(h.filePath, data, 0644); writeErr != nil {
+		slog.Error("failed to write health file", "path", h.filePath, "err", writeErr)
+	} else {
+		slog.Debug("health status updated", "path", h.filePath, "lastError", s.LastError != "")
+	}
 }

 // runHealthcheck liest die Health-Datei und prüft, ob der Daemon healthy ist.
@@ -68,6 +73,7 @@ func runHealthcheck() error {
 		stateFilepath = "state.json"
 	}
 	healthPath := filepath.Join(filepath.Dir(stateFilepath), healthFile)
+	slog.Debug("running healthcheck", "healthPath", healthPath)

 	data, err := os.ReadFile(healthPath)
 	if err != nil {
@@ -78,10 +84,13 @@ func runHealthcheck() error {
 		return fmt.Errorf("invalid health file: %w", err)
 	}
 	if s.LastError != "" {
+		slog.Warn("healthcheck: last sync had an error", "lastError", s.LastError)
 		return fmt.Errorf("last sync failed: %s", s.LastError)
 	}
 	if time.Since(s.LastSync) > maxSyncAge() {
+		slog.Warn("healthcheck: last sync too old", "age", time.Since(s.LastSync).Round(time.Second))
 		return fmt.Errorf("last sync too old: %s ago", time.Since(s.LastSync).Round(time.Second))
 	}
+	slog.Debug("healthcheck passed", "lastSync", s.LastSync.Format("2006/01/02 15:04:05"))
 	return nil
 }
--- a/cmd/mcbdd/logger.go
+++ b/cmd/mcbdd/logger.go
@@ -0,0 +1,115 @@
+package main
+
+import (
+	"context"
+	"fmt"
+	"io"
+	"log/slog"
+	"strings"
+	"sync"
+	"time"
+)
+
+// bracketHandler ist ein slog.Handler, der Log-Nachrichten im Format
+// "2006/01/02 15:04:05 [LEVEL] message key=value" ausgibt.
+// Die Level-Tags [INFO], [WARN], [ERROR] und [DEBUG] ermöglichen eine
+// schnelle visuelle Zuordnung in Container-Logs.
+type bracketHandler struct {
+	level slog.Level
+	out   io.Writer
+	mu    *sync.Mutex
+	attrs []slog.Attr
+}
+
+func newBracketHandler(out io.Writer, level slog.Level) *bracketHandler {
+	return &bracketHandler{
+		level: level,
+		out:   out,
+		mu:    &sync.Mutex{},
+	}
+}
+
+func (h *bracketHandler) Enabled(_ context.Context, level slog.Level) bool {
+	return level >= h.level
+}
+
+func (h *bracketHandler) Handle(_ context.Context, r slog.Record) error {
+	var levelTag string
+	switch {
+	case r.Level >= slog.LevelError:
+		levelTag = "[ERROR]"
+	case r.Level >= slog.LevelWarn:
+		levelTag = "[WARN]"
+	case r.Level >= slog.LevelInfo:
+		levelTag = "[INFO]"
+	default:
+		levelTag = "[DEBUG]"
+	}
+
+	var b strings.Builder
+	b.WriteString(r.Time.Format("2006/01/02 15:04:05"))
+	b.WriteByte(' ')
+	b.WriteString(levelTag)
+	b.WriteByte(' ')
+	b.WriteString(r.Message)
+
+	writeAttr := func(a slog.Attr) bool {
+		a.Value = a.Value.Resolve()
+		if a.Equal(slog.Attr{}) {
+			return true
+		}
+		b.WriteByte(' ')
+		b.WriteString(a.Key)
+		b.WriteByte('=')
+		b.WriteString(formatAttrValue(a.Value))
+		return true
+	}
+
+	for _, a := range h.attrs {
+		writeAttr(a)
+	}
+	r.Attrs(writeAttr)
+
+	b.WriteByte('\n')
+
+	h.mu.Lock()
+	defer h.mu.Unlock()
+	_, err := h.out.Write([]byte(b.String()))
+	return err
+}
+
+func (h *bracketHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	newAttrs := make([]slog.Attr, len(h.attrs)+len(attrs))
+	copy(newAttrs, h.attrs)
+	copy(newAttrs[len(h.attrs):], attrs)
+	return &bracketHandler{
+		level: h.level,
+		out:   h.out,
+		mu:    h.mu,
+		attrs: newAttrs,
+	}
+}
+
+func (h *bracketHandler) WithGroup(_ string) slog.Handler {
+	// Gruppen werden für dieses Projekt nicht benötigt.
+	return h
+}
+
+// formatAttrValue formatiert einen slog.Value als String.
+// String-Werte mit Leerzeichen oder Sonderzeichen werden in Anführungszeichen gesetzt.
+func formatAttrValue(v slog.Value) string {
+	switch v.Kind() {
+	case slog.KindString:
+		s := v.String()
+		if s == "" || strings.ContainsAny(s, " \t\n\"\\") {
+			return fmt.Sprintf("%q", s)
+		}
+		return s
+	case slog.KindTime:
+		return v.Time().Format(time.RFC3339)
+	case slog.KindDuration:
+		return v.Duration().String()
+	default:
+		return fmt.Sprintf("%v", v.Any())
+	}
+}
--- a/cmd/mcbdd/mailcow.go
+++ b/cmd/mcbdd/mailcow.go
@@ -11,12 +11,15 @@ func (d *Daemon) getUserPass(ctx context.Context, username string) (string, erro
 	pass, ok := d.userTokens[username]
 	d.userTokensLock.RUnlock()
 	if ok {
+		slog.DebugContext(ctx, "using cached app password", "user", username)
 		return pass, nil
 	}
+	slog.DebugContext(ctx, "no cached password found, creating new app password", "user", username)
 	pp, err := d.mailcowClient.GetAppPasswords(ctx, username)
 	if err != nil {
 		return "", err
 	}
+	slog.DebugContext(ctx, "retrieved existing app passwords", "user", username, "total", len(pp))
 	oldIDs := make([]int, 0)
 	for _, p := range pp {
 		if p.Name == ConstUsertokenName {
--- a/cmd/mcbdd/main.go
+++ b/cmd/mcbdd/main.go
@@ -58,9 +58,7 @@ func initLogLevel() {
 	default:
 		level = slog.LevelInfo
 	}
-	slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{
-		Level: level,
-	})))
+	slog.SetDefault(slog.New(newBracketHandler(os.Stderr, level)))
 }

 func main() {
@@ -102,8 +100,9 @@ func run() error {
 	slog.Info("waiting for dependent services to become ready", "delay", startupDelay)
 	select {
 	case <-time.After(startupDelay):
+		slog.Debug("startup delay completed, proceeding with initialization")
 	case <-ctx.Done():
-		slog.Info("shutdown signal received during startup, exiting")
+		slog.Warn("shutdown signal received during startup, exiting")
 		return nil
 	}

@@ -125,6 +124,13 @@ func run() error {
 		return err
 	}
 	slog.Info("sync interval configured", "interval", syncInterval)
+	slog.Debug("configuration summary",
+		"MAILCOW_BASE", mailcowBase,
+		"CALENDAR_NAME", calendarName,
+		"NOTIFICATION_ENABLED", notificationEnabled,
+		"MAILCOW_RESOLVE_HOST", os.Getenv("MAILCOW_RESOLVE_HOST"),
+		"STATEFILE", os.Getenv("STATEFILE"),
+	)

 	notificationTrigger := "PT8H"
 	if notificationEnabled {
@@ -138,6 +144,8 @@ func run() error {
 		}
 		notificationTrigger = trigger
 		slog.Info("birthday notifications enabled", "time", notificationTime, "trigger", notificationTrigger)
+	} else {
+		slog.Debug("birthday notifications disabled")
 	}
 	d := &Daemon{
 		userTokens:          make(map[string]string),
@@ -153,6 +161,7 @@ func run() error {
 	if len(d.stateFilepath) == 0 {
 		d.stateFilepath = "state.json"
 	}
+	slog.Debug("state file path", "path", d.stateFilepath)
 	d.health = newHealthState(d.stateFilepath)
 	d.mailcowClient = mailcow.New(
 		d.httpClient,
@@ -162,6 +171,7 @@ func run() error {
 	if err := d.loadState(); err != nil {
 		return err
 	}
+	slog.Info("initialization complete, entering daemon loop")
 	d.daemonLoop(ctx)
 	return nil
 }
@@ -176,12 +186,17 @@ func (d *Daemon) daemonLoop(ctx context.Context) {
 		default:
 		}

+		slog.Debug("starting sync cycle")
+		start := time.Now()
 		err := d.daemonRun()
 		d.health.update(err)
 		if err != nil {
 			slog.Error("error while syncing birthdays", "err", err)
+		} else {
+			slog.Info("sync cycle completed", "duration", time.Since(start).Round(time.Millisecond))
 		}

+		slog.Debug("waiting for next sync cycle", "interval", d.syncInterval)
 		// Auf nächsten Zyklus oder Shutdown-Signal warten.
 		timer := time.NewTimer(d.syncInterval)
 		select {
@@ -200,11 +215,12 @@ func (d *Daemon) daemonLoop(ctx context.Context) {
 }

 func (d *Daemon) daemonRun() error {
+	slog.Debug("fetching mailboxes from mailcow API")
 	mb, err := d.mailcowClient.GetMailboxes(context.Background())
 	if err != nil {
 		return fmt.Errorf("error fetching mailboxes: %w", err)
 	}
-	slog.Debug("fetched mailboxes", "count", len(mb))
+	slog.Info("fetched mailboxes", "count", len(mb))
 	eg := sync.WaitGroup{}
 	for _, m := range mb {
 		eg.Go(func() {
@@ -238,6 +254,7 @@ func (d *Daemon) processUser(ctx context.Context, m mailcow.Mailbox) error {
 	}
 	davclient := webdav.HTTPClientWithBasicAuth(d.httpClient, m.Username, pass)
 	if d.oldCalendarName != "" {
+		slog.DebugContext(ctx, "cleaning up old calendar", "user", m.Username, "oldName", d.oldCalendarName)
 		if err := d.cleanupOldCalendar(ctx, davclient, m.Username, d.oldCalendarName); err != nil {
 			slog.WarnContext(ctx, "error cleaning up old calendar", "err", err, "user", m.Username)
 		}
@@ -253,12 +270,14 @@ func (d *Daemon) processUser(ctx context.Context, m mailcow.Mailbox) error {
 		}
 		return fmt.Errorf("error getting birthdays from carddav: %w", err)
 	}
+	slog.DebugContext(ctx, "found birthday contacts", "user", m.Username, "count", len(bb))
 	if err := d.ensureBirthdayCal(ctx, davclient, m.Username); err != nil {
 		return fmt.Errorf("error creating birthday calendar in caldav: %w", err)
 	}
 	if err := d.syncBirthdaysToCal(ctx, davclient, m.Username, bb); err != nil {
 		return fmt.Errorf("error syncing birthday events to caldav: %w", err)
 	}
+	slog.DebugContext(ctx, "user processing complete", "user", m.Username)
 	return nil
 }

@@ -272,6 +291,7 @@ func runCleanup() error {
 	oldCalendarName := os.Args[2]

 	slog.Info("starting calendar cleanup", "calendarName", oldCalendarName)
+	slog.Debug("loading environment configuration for cleanup")

 	mailcowBase := os.Getenv("MAILCOW_BASE")
 	if mailcowBase == "" {
@@ -309,8 +329,10 @@ func runCleanup() error {
 	}

 	processed, skipped := 0, 0
+	slog.Debug("starting cleanup for all mailboxes", "totalMailboxes", len(mb))
 	for _, m := range mb {
 		if !m.IsActive() {
+			slog.Debug("skipping inactive mailbox during cleanup", "user", m.Username)
 			continue
 		}
 		d.userTokensLock.RLock()
@@ -322,9 +344,12 @@ func runCleanup() error {
 			continue
 		}
 		ctx := context.Background()
+		slog.Debug("cleaning up calendar for user", "user", m.Username, "calendar", oldCalendarName)
 		davclient := webdav.HTTPClientWithBasicAuth(d.httpClient, m.Username, pass)
 		if err := d.cleanupOldCalendar(ctx, davclient, m.Username, oldCalendarName); err != nil {
 			slog.Error("error cleaning up calendar", "user", m.Username, "err", err)
+		} else {
+			slog.Debug("calendar cleanup successful for user", "user", m.Username)
 		}
 		processed++
 	}
--- a/cmd/mcbdd/persist.go
+++ b/cmd/mcbdd/persist.go
@@ -10,22 +10,25 @@ import (
 )

 func (d *Daemon) loadState() error {
+	slog.Debug("loading state file", "path", d.stateFilepath)
 	stateVer := struct {
 		Version int `json:"version"`
 	}{}
 	if err := d.loadFromDisk(&stateVer); err != nil {
 		return fmt.Errorf("cant detect state version: %w", err)
 	}
+	slog.Debug("detected state version", "version", stateVer.Version)
 	var storedCalendarName string
 	switch stateVer.Version {
 	case 0:
-		slog.Warn("loading old state version", "stateVer", stateVer.Version)
+		slog.Warn("loading old state version, migration required", "stateVer", stateVer.Version)
 		if err := d.loadFromDisk(&d.userTokens); err != nil {
 			return fmt.Errorf("cant load state v%d: %w", stateVer.Version, err)
 		}
 		slog.Debug("loaded state", "version", stateVer.Version, "users", len(d.userTokens))
 		d.stateUnsaved = true
 	case 1:
+		slog.Warn("loading state v1, migration to v2 required", "stateVer", stateVer.Version)
 		state := struct {
 			Version    int               `json:"version"`
 			UserTokens map[string]string `json:"userTokens"`
@@ -42,6 +45,7 @@ func (d *Daemon) loadState() error {
 		}
 		d.stateUnsaved = true
 	case 2:
+		slog.Debug("loading current state format", "stateVer", stateVer.Version)
 		state := struct {
 			Version      int               `json:"version"`
 			UserTokens   map[string]string `json:"userTokens"`
@@ -59,6 +63,7 @@ func (d *Daemon) loadState() error {
 		}
 		storedCalendarName = state.CalendarName
 	}
+	slog.Info("state loaded", "users", len(d.userTokens))
 	if storedCalendarName != "" && storedCalendarName != d.calendarName {
 		slog.Info("calendar name changed, old calendars will be cleaned up",
 			"old", storedCalendarName, "new", d.calendarName)
@@ -69,6 +74,7 @@ func (d *Daemon) loadState() error {
 }

 func (d *Daemon) saveState() error {
+	slog.Debug("saving state to disk", "path", d.stateFilepath, "users", len(d.userTokens))
 	encTokens := make(map[string]string, len(d.userTokens))
 	for k, v := range d.userTokens {
 		encTokens[k] = base64.StdEncoding.EncodeToString([]byte(v))
@@ -82,13 +88,18 @@ func (d *Daemon) saveState() error {
 		UserTokens:   encTokens,
 		CalendarName: d.calendarName,
 	}
-	return d.saveToDisk(state)
+	if err := d.saveToDisk(state); err != nil {
+		return err
+	}
+	slog.Debug("state saved successfully")
+	return nil
 }

 func (d *Daemon) loadFromDisk(state any) error {
 	f, err := os.OpenFile(d.stateFilepath, os.O_RDONLY, 0o660)
 	if err != nil {
 		if errors.Is(err, os.ErrNotExist) {
+			slog.Debug("state file does not exist, starting fresh", "path", d.stateFilepath)
 			return nil
 		}
 		return err
--- a/docs/troubleshooting.md
+++ b/docs/troubleshooting.md
@@ -34,12 +34,12 @@ docker compose exec birthdaydaemon /mailcow-birthday-daemon cleanup Birthdays
 **Beispielausgabe:**

 ```
-2026/03/28 23:46:22 INFO starting calendar cleanup calendarName=Birthdays
-2026/03/28 23:46:22 INFO using internal resolve host for connections resolveHost=nginx-mailcow
-2026/03/28 23:46:22 INFO removed old birthday calendar user=user1@example.com calendar=Birthdays
-2026/03/28 23:46:23 INFO removed old birthday calendar user=user2@example.com calendar=Birthdays
-2026/03/28 23:46:23 INFO removed old birthday calendar user=user3@example.com calendar=Birthdays
-2026/03/28 23:46:24 INFO cleanup finished processed=5 skipped=0
+2026/03/28 23:46:22 [INFO] starting calendar cleanup calendarName=Birthdays
+2026/03/28 23:46:22 [INFO] using internal resolve host for connections resolveHost=nginx-mailcow
+2026/03/28 23:46:22 [INFO] removed old birthday calendar user=user1@example.com calendar=Birthdays
+2026/03/28 23:46:23 [INFO] removed old birthday calendar user=user2@example.com calendar=Birthdays
+2026/03/28 23:46:23 [INFO] removed old birthday calendar user=user3@example.com calendar=Birthdays
+2026/03/28 23:46:24 [INFO] cleanup finished processed=5 skipped=0
 ```

 > **Hinweis:** Der Daemon muss vorher mindestens einmal gelaufen sein, damit App-Passwörter im State-File vorhanden sind. Benutzer ohne gespeichertes Passwort werden übersprungen.