feat: implement structured logging and error handling in discord-bot

2026-04-09 05:06:38 +09:00 · 2026-04-09 05:06:38 +09:00 · 1d3e223dbb
commit 1d3e223dbb
parent 4186f864f9
6 changed files with 187 additions and 32 deletions
--- a/discord-bot/.env.example
+++ b/discord-bot/.env.example
@ -2,3 +2,5 @@ DISCORD_TOKEN=your-bot-token-here
 GUILD_ID=your-guild-id-here
 HA_GATEWAY_ADDR=localhost:50051
 OTEL_ENDPOINT=
+LOG_LEVEL=info
+LOG_FORMAT=text
--- a/discord-bot/cmd/bot/main.go
+++ b/discord-bot/cmd/bot/main.go
@ -2,7 +2,6 @@ package main

 import (
 	"context"
-	"log/slog"
 	"os"
 	"os/signal"
 	"syscall"
@ -15,6 +14,7 @@ import (
 	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/adapters/secondary/gateway"
 	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/app"
 	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/config"
+	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/logger"
 	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/telemetry"
 )

@ -25,27 +25,37 @@ func main() {

 	cfg, err := config.Load()
 	if err != nil {
-		slog.Error("config error", "err", err)
+		os.Stderr.WriteString("config error: " + err.Error() + "\n")
 		os.Exit(1)
 	}

+	log := logger.New(cfg.LogFormat, cfg.LogLevel)
+	log.Info("starting discord-bot",
+		"version", version,
+		"ha_gateway_addr", cfg.HAGatewayAddr,
+		"discord_token", redactToken(cfg.DiscordToken),
+		"log_level", cfg.LogLevel,
+		"log_format", cfg.LogFormat,
+	)
+
 	ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM)
 	defer stop()
+	ctx = logger.WithLogger(ctx, log)

 	shutdown, err := telemetry.Setup(ctx, cfg, version)
 	if err != nil {
-		slog.Error("telemetry setup failed", "err", err)
+		log.Error("telemetry setup failed", "err", err)
 		os.Exit(1)
 	}

-	haClient, err := gateway.New(ctx, cfg.HAGatewayAddr)
+	haClient, err := gateway.New(ctx, cfg.HAGatewayAddr, log)
 	if err != nil {
-		slog.Error("ha-gateway client setup failed", "err", err)
+		log.Error("ha-gateway client setup failed", "err", err)
 		os.Exit(1)
 	}
 	defer func() {
 		if err := haClient.Close(); err != nil {
-			slog.Error("ha-gateway client close failed", "err", err)
+			log.Error("ha-gateway client close failed", "err", err)
 		}
 	}()

@ -53,7 +63,7 @@ func main() {

 	session, err := discordgo.New("Bot " + cfg.DiscordToken)
 	if err != nil {
-		slog.Error("create discord session failed", "err", err)
+		log.Error("create discord session failed", "err", err)
 		os.Exit(1)
 	}
 	session.Identify.Intents = discordgo.IntentsGuilds
@ -62,12 +72,13 @@ func main() {
 	handler.Register(session)

 	if err := session.Open(); err != nil {
-		slog.Error("open discord session failed", "err", err)
+		log.Error("open discord session failed", "err", err)
 		os.Exit(1)
 	}
+	log.Info("discord session ready", "bot_user", session.State.User.Username)

 	if err := discordadapter.RegisterCommands(session, cfg.GuildID); err != nil {
-		slog.Error("register discord commands failed", "err", err)
+		log.Error("register discord commands failed", "err", err)
 		os.Exit(1)
 	}

@ -75,18 +86,29 @@ func main() {
 	if cfg.GuildID != "" {
 		scope = cfg.GuildID
 	}
-	slog.Info("discord bot started", "command_scope", scope, "ha_gateway_addr", cfg.HAGatewayAddr, "version", version)
+	log.Info("discord bot started", "command_scope", scope, "ha_gateway_addr", cfg.HAGatewayAddr, "version", version)

 	<-ctx.Done()
-	slog.InfoContext(ctx, "shutting down discord bot")
+	log.Info("shutdown signal received, closing session")

 	if err := session.Close(); err != nil {
-		slog.ErrorContext(ctx, "close discord session failed", "err", err)
+		log.Error("close discord session failed", "err", err)
 	}
+	log.Info("shutdown complete")

 	shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
 	defer cancel()
 	if err := shutdown(shutdownCtx); err != nil {
-		slog.Error("telemetry shutdown error", "err", err)
+		log.Error("telemetry shutdown error", "err", err)
 	}
 }
+
+func redactToken(token string) string {
+	if token == "" {
+		return "[not set]"
+	}
+	if len(token) <= 8 {
+		return "[set]"
+	}
+	return token[:8] + "..."
+}
--- a/discord-bot/internal/adapters/primary/discord/handler.go
+++ b/discord-bot/internal/adapters/primary/discord/handler.go
@ -8,6 +8,7 @@ import (
 	"time"

 	apppkg "gitea.nik4nao.com/nik/home-services/discord-bot/internal/app"
+	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/logger"
 	"github.com/bwmarrin/discordgo"
 )

@ -36,6 +37,7 @@ func (h *Handler) Register(s *discordgo.Session) {
 func (h *Handler) onInteractionCreate(s *discordgo.Session, i *discordgo.InteractionCreate) {
 	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
 	defer cancel()
+	ctx = logger.WithLogger(ctx, interactionLogger(ctx, i))

 	switch i.Type {
 	case discordgo.InteractionApplicationCommand:
@ -46,9 +48,13 @@ func (h *Handler) onInteractionCreate(s *discordgo.Session, i *discordgo.Interac
 }

 func (h *Handler) handleApplicationCommand(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) {
+	log := logger.FromContext(ctx)
+	start := time.Now()
+	log.Debug("command received")
+
 	data := i.ApplicationCommandData()
 	if len(data.Options) == 0 {
-		h.respondError(ctx, s, i.Interaction, true, fmt.Errorf("missing subcommand"))
+		h.respondError(ctx, s, i.Interaction, true, start, fmt.Errorf("missing subcommand"))
 		return
 	}

@ -57,44 +63,56 @@ func (h *Handler) handleApplicationCommand(ctx context.Context, s *discordgo.Ses
 	case "light.list":
 		msg, err := h.app.HandleLightList(ctx)
 		if err != nil {
-			h.respondError(ctx, s, i.Interaction, false, err)
+			h.respondError(ctx, s, i.Interaction, false, start, err)
 			return
 		}
 		h.respondMessage(ctx, s, i.Interaction, msg, false)
+		log.Info("command handled", "duration_ms", time.Since(start).Milliseconds())
 	case "switch.list":
 		msg, err := h.app.HandleSwitchList(ctx)
 		if err != nil {
-			h.respondError(ctx, s, i.Interaction, false, err)
+			h.respondError(ctx, s, i.Interaction, false, start, err)
 			return
 		}
 		h.respondMessage(ctx, s, i.Interaction, msg, false)
+		log.Info("command handled", "duration_ms", time.Since(start).Milliseconds())
 	case "light.on":
 		if err := h.deferResponse(s, i.Interaction, true); err != nil {
-			slog.ErrorContext(ctx, "defer discord response failed", "err", err)
+			log.Error("discord response failed",
+				"duration_ms", time.Since(start).Milliseconds(),
+				"error", err.Error(),
+			)
 			return
 		}
 		msg, err := h.app.HandleLightOn(ctx, requiredStringOption(sub, "light"), optionalUint32Option(sub, "brightness"), optionalUint32Option(sub, "color_temp"))
-		h.followup(ctx, s, i.Interaction, msg, true, err)
+		h.followup(ctx, s, i.Interaction, msg, true, start, err)
 	case "light.off":
 		if err := h.deferResponse(s, i.Interaction, true); err != nil {
-			slog.ErrorContext(ctx, "defer discord response failed", "err", err)
+			log.Error("discord response failed",
+				"duration_ms", time.Since(start).Milliseconds(),
+				"error", err.Error(),
+			)
 			return
 		}
 		msg, err := h.app.HandleLightOff(ctx, requiredStringOption(sub, "light"), optionalUint32Option(sub, "transition"))
-		h.followup(ctx, s, i.Interaction, msg, true, err)
+		h.followup(ctx, s, i.Interaction, msg, true, start, err)
 	case "light.toggle":
 		if err := h.deferResponse(s, i.Interaction, true); err != nil {
-			slog.ErrorContext(ctx, "defer discord response failed", "err", err)
+			log.Error("discord response failed",
+				"duration_ms", time.Since(start).Milliseconds(),
+				"error", err.Error(),
+			)
 			return
 		}
 		msg, err := h.app.HandleLightToggle(ctx, requiredStringOption(sub, "light"))
-		h.followup(ctx, s, i.Interaction, msg, true, err)
+		h.followup(ctx, s, i.Interaction, msg, true, start, err)
 	default:
-		h.respondError(ctx, s, i.Interaction, true, fmt.Errorf("unsupported command: %s.%s", data.Name, sub.Name))
+		h.respondError(ctx, s, i.Interaction, true, start, fmt.Errorf("unsupported command: %s.%s", data.Name, sub.Name))
 	}
 }

 func (h *Handler) handleAutocomplete(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) {
+	log := logger.FromContext(ctx)
 	data := i.ApplicationCommandData()
 	var (
 		choices []apppkg.Choice
@ -110,7 +128,7 @@ func (h *Handler) handleAutocomplete(ctx context.Context, s *discordgo.Session,
 		choices = nil
 	}
 	if err != nil {
-		slog.ErrorContext(ctx, "autocomplete failed", "command", data.Name, "err", err)
+		log.Error("command failed", "error", err.Error())
 		choices = nil
 	}

@ -135,7 +153,7 @@ func (h *Handler) handleAutocomplete(ctx context.Context, s *discordgo.Session,
 			Choices: respChoices,
 		},
 	}); err != nil {
-		slog.ErrorContext(ctx, "discord autocomplete response failed", "err", err)
+		log.Error("discord response failed", "error", err.Error())
 	}
 }

@ -154,6 +172,7 @@ func (h *Handler) deferResponse(s *discordgo.Session, interaction *discordgo.Int
 }

 func (h *Handler) respondMessage(ctx context.Context, s *discordgo.Session, interaction *discordgo.Interaction, content string, ephemeral bool) {
+	log := logger.FromContext(ctx)
 	data := &discordgo.InteractionResponseData{Content: content}
 	if ephemeral {
 		data.Flags = discordgo.MessageFlagsEphemeral
@ -162,29 +181,55 @@ func (h *Handler) respondMessage(ctx context.Context, s *discordgo.Session, inte
 		Type: discordgo.InteractionResponseChannelMessageWithSource,
 		Data: data,
 	}); err != nil {
-		slog.ErrorContext(ctx, "discord response failed", "err", err)
+		log.Error("discord response failed", "error", err.Error())
 	}
 }

-func (h *Handler) respondError(ctx context.Context, s *discordgo.Session, interaction *discordgo.Interaction, ephemeral bool, err error) {
-	slog.ErrorContext(ctx, "discord command failed", "err", err)
+func (h *Handler) respondError(ctx context.Context, s *discordgo.Session, interaction *discordgo.Interaction, ephemeral bool, start time.Time, err error) {
+	logger.FromContext(ctx).Error("command failed",
+		"duration_ms", time.Since(start).Milliseconds(),
+		"error", err.Error(),
+	)
 	h.respondMessage(ctx, s, interaction, fmt.Sprintf("Error: %v", err), ephemeral)
 }

-func (h *Handler) followup(ctx context.Context, s *discordgo.Session, interaction *discordgo.Interaction, content string, ephemeral bool, err error) {
+func (h *Handler) followup(ctx context.Context, s *discordgo.Session, interaction *discordgo.Interaction, content string, ephemeral bool, start time.Time, err error) {
+	log := logger.FromContext(ctx)
 	if err != nil {
-		slog.ErrorContext(ctx, "discord action failed", "err", err)
+		log.Error("command failed",
+			"duration_ms", time.Since(start).Milliseconds(),
+			"error", err.Error(),
+		)
 		content = fmt.Sprintf("Error: %v", err)
+	} else {
+		log.Info("command handled", "duration_ms", time.Since(start).Milliseconds())
 	}
 	params := &discordgo.WebhookParams{Content: content}
 	if ephemeral {
 		params.Flags = discordgo.MessageFlagsEphemeral
 	}
 	if _, followErr := s.FollowupMessageCreate(interaction, true, params); followErr != nil {
-		slog.ErrorContext(ctx, "discord followup failed", "err", followErr)
+		log.Error("discord response failed", "error", followErr.Error())
 	}
 }

+func interactionLogger(ctx context.Context, i *discordgo.InteractionCreate) *slog.Logger {
+	log := logger.FromContext(ctx)
+	data := i.ApplicationCommandData()
+	command := data.Name
+	user := ""
+	if i.Member != nil && i.Member.User != nil {
+		user = i.Member.User.Username
+	} else if i.User != nil {
+		user = i.User.Username
+	}
+	return log.With(
+		"command", command,
+		"user", user,
+		"guild", i.GuildID,
+	)
+}
+
 func requiredStringOption(sub *discordgo.ApplicationCommandInteractionDataOption, name string) string {
 	for _, opt := range sub.Options {
 		if opt.Name == name {
--- a/discord-bot/internal/adapters/secondary/gateway/client.go
+++ b/discord-bot/internal/adapters/secondary/gateway/client.go
@ -3,8 +3,11 @@ package gateway
 import (
 	"context"
 	"fmt"
+	"log/slog"
+	"time"

 	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/core/ports/driven"
+	"gitea.nik4nao.com/nik/home-services/discord-bot/internal/logger"
 	hav1 "gitea.nik4nao.com/nik/home-services/gen/ha/v1"
 	"go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc"
 	"google.golang.org/grpc"
@ -15,9 +18,10 @@ type Client struct {
 	conn         *grpc.ClientConn
 	lightClient  hav1.LightServiceClient
 	switchClient hav1.SwitchServiceClient
+	log          *slog.Logger
 }

-func New(ctx context.Context, addr string) (*Client, error) {
+func New(ctx context.Context, addr string, log *slog.Logger) (*Client, error) {
 	conn, err := grpc.NewClient(
 		addr,
 		grpc.WithTransportCredentials(insecure.NewCredentials()),
@ -31,6 +35,7 @@ func New(ctx context.Context, addr string) (*Client, error) {
 		conn:         conn,
 		lightClient:  hav1.NewLightServiceClient(conn),
 		switchClient: hav1.NewSwitchServiceClient(conn),
+		log:          log,
 	}, nil
 }

@ -42,10 +47,17 @@ func (c *Client) Close() error {
 }

 func (c *Client) ListLights(ctx context.Context) ([]driven.Light, error) {
+	start := time.Now()
+	log := logger.FromContext(ctx).With("grpc.method", "LightService/ListLights")
 	resp, err := c.lightClient.ListLights(ctx, &hav1.ListLightsRequest{})
 	if err != nil {
+		log.Error("grpc call failed",
+			"duration_ms", time.Since(start).Milliseconds(),
+			"error", err.Error(),
+		)
 		return nil, fmt.Errorf("list lights: %w", err)
 	}
+	log.Debug("grpc call completed", "duration_ms", time.Since(start).Milliseconds())

 	lights := make([]driven.Light, 0, len(resp.GetLights()))
 	for _, light := range resp.GetLights() {
@ -64,10 +76,17 @@ func (c *Client) ListLights(ctx context.Context) ([]driven.Light, error) {
 }

 func (c *Client) ListSwitches(ctx context.Context) ([]driven.Switch, error) {
+	start := time.Now()
+	log := logger.FromContext(ctx).With("grpc.method", "SwitchService/ListSwitches")
 	resp, err := c.switchClient.ListSwitches(ctx, &hav1.ListSwitchesRequest{})
 	if err != nil {
+		log.Error("grpc call failed",
+			"duration_ms", time.Since(start).Milliseconds(),
+			"error", err.Error(),
+		)
 		return nil, fmt.Errorf("list switches: %w", err)
 	}
+	log.Debug("grpc call completed", "duration_ms", time.Since(start).Milliseconds())

 	switches := make([]driven.Switch, 0, len(resp.GetSwitches()))
 	for _, sw := range resp.GetSwitches() {
@ -82,6 +101,8 @@ func (c *Client) ListSwitches(ctx context.Context) ([]driven.Switch, error) {
 }

 func (c *Client) TurnOnLight(ctx context.Context, entityID string, brightnessPct *uint32, colorTempKelvin *uint32) error {
+	start := time.Now()
+	log := logger.FromContext(ctx).With("grpc.method", "LightService/TurnOn")
 	req := &hav1.TurnOnRequest{EntityId: entityID}
 	if brightnessPct != nil {
 		req.BrightnessPct = brightnessPct
@ -91,26 +112,45 @@ func (c *Client) TurnOnLight(ctx context.Context, entityID string, brightnessPct
 	}

 	if _, err := c.lightClient.TurnOn(ctx, req); err != nil {
+		log.Error("grpc call failed",
+			"duration_ms", time.Since(start).Milliseconds(),
+			"error", err.Error(),
+		)
 		return fmt.Errorf("turn on light %s: %w", entityID, err)
 	}
+	log.Debug("grpc call completed", "duration_ms", time.Since(start).Milliseconds())
 	return nil
 }

 func (c *Client) TurnOffLight(ctx context.Context, entityID string, transition *uint32) error {
+	start := time.Now()
+	log := logger.FromContext(ctx).With("grpc.method", "LightService/TurnOff")
 	req := &hav1.TurnOffRequest{EntityId: entityID}
 	if transition != nil {
 		req.Transition = transition
 	}

 	if _, err := c.lightClient.TurnOff(ctx, req); err != nil {
+		log.Error("grpc call failed",
+			"duration_ms", time.Since(start).Milliseconds(),
+			"error", err.Error(),
+		)
 		return fmt.Errorf("turn off light %s: %w", entityID, err)
 	}
+	log.Debug("grpc call completed", "duration_ms", time.Since(start).Milliseconds())
 	return nil
 }

 func (c *Client) ToggleLight(ctx context.Context, entityID string) error {
+	start := time.Now()
+	log := logger.FromContext(ctx).With("grpc.method", "LightService/Toggle")
 	if _, err := c.lightClient.Toggle(ctx, &hav1.ToggleRequest{EntityId: entityID}); err != nil {
+		log.Error("grpc call failed",
+			"duration_ms", time.Since(start).Milliseconds(),
+			"error", err.Error(),
+		)
 		return fmt.Errorf("toggle light %s: %w", entityID, err)
 	}
+	log.Debug("grpc call completed", "duration_ms", time.Since(start).Milliseconds())
 	return nil
 }
--- a/discord-bot/internal/config/config.go
+++ b/discord-bot/internal/config/config.go
@ -10,6 +10,8 @@ type Config struct {
 	GuildID       string
 	HAGatewayAddr string
 	OTELEndpoint  string
+	LogLevel      string
+	LogFormat     string
 }

 func Load() (*Config, error) {
@ -28,5 +30,14 @@ func Load() (*Config, error) {
 		GuildID:       os.Getenv("GUILD_ID"),
 		HAGatewayAddr: addr,
 		OTELEndpoint:  os.Getenv("OTEL_ENDPOINT"),
+		LogLevel:      getenvDefault("LOG_LEVEL", "info"),
+		LogFormat:     getenvDefault("LOG_FORMAT", "json"),
 	}, nil
 }
+
+func getenvDefault(key, fallback string) string {
+	if v := os.Getenv(key); v != "" {
+		return v
+	}
+	return fallback
+}
--- a/discord-bot/internal/logger/logger.go
+++ b/discord-bot/internal/logger/logger.go
@ -0,0 +1,35 @@
+package logger
+
+import (
+	"context"
+	"fmt"
+	"log/slog"
+	"os"
+)
+
+type contextKey struct{}
+
+func New(format, level string) *slog.Logger {
+	var parsed slog.Level
+	if err := parsed.UnmarshalText([]byte(level)); err != nil {
+		_, _ = fmt.Fprintf(os.Stderr, "invalid log level %q, falling back to info\n", level)
+		parsed = slog.LevelInfo
+	}
+
+	opts := &slog.HandlerOptions{Level: parsed}
+	if format == "json" {
+		return slog.New(slog.NewJSONHandler(os.Stdout, opts))
+	}
+	return slog.New(slog.NewTextHandler(os.Stdout, opts))
+}
+
+func WithLogger(ctx context.Context, l *slog.Logger) context.Context {
+	return context.WithValue(ctx, contextKey{}, l)
+}
+
+func FromContext(ctx context.Context) *slog.Logger {
+	if l, ok := ctx.Value(contextKey{}).(*slog.Logger); ok && l != nil {
+		return l
+	}
+	return slog.Default()
+}