From 1d3e223dbb15f54d4018943ee10b45816a2c8bc6 Mon Sep 17 00:00:00 2001 From: Nik Afiq Date: Thu, 9 Apr 2026 05:06:38 +0900 Subject: [PATCH] feat: implement structured logging and error handling in discord-bot --- discord-bot/.env.example | 2 + discord-bot/cmd/bot/main.go | 48 ++++++++--- .../adapters/primary/discord/handler.go | 81 ++++++++++++++----- .../adapters/secondary/gateway/client.go | 42 +++++++++- discord-bot/internal/config/config.go | 11 +++ discord-bot/internal/logger/logger.go | 35 ++++++++ 6 files changed, 187 insertions(+), 32 deletions(-) create mode 100644 discord-bot/internal/logger/logger.go diff --git a/discord-bot/.env.example b/discord-bot/.env.example index b6e1302..67e373d 100644 --- 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 diff --git a/discord-bot/cmd/bot/main.go b/discord-bot/cmd/bot/main.go index fc876b7..dd78584 100644 --- 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] + "..." +} diff --git a/discord-bot/internal/adapters/primary/discord/handler.go b/discord-bot/internal/adapters/primary/discord/handler.go index f3271e8..27ffb2b 100644 --- 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 { diff --git a/discord-bot/internal/adapters/secondary/gateway/client.go b/discord-bot/internal/adapters/secondary/gateway/client.go index b56fd9e..6681125 100644 --- 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 } diff --git a/discord-bot/internal/config/config.go b/discord-bot/internal/config/config.go index 44d3cdc..3acfe37 100644 --- 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 +} diff --git a/discord-bot/internal/logger/logger.go b/discord-bot/internal/logger/logger.go new file mode 100644 index 0000000..2232a97 --- /dev/null +++ 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() +}