From 1646762081a8e6a630c0085659b3080b48982d67 Mon Sep 17 00:00:00 2001 From: William Perron Date: Tue, 30 Jan 2024 21:07:47 -0500 Subject: [PATCH] wip: refactor command logging and tracing --- cmd/themis-server/main.go | 84 ++++++++++++++++++--------------------- 1 file changed, 39 insertions(+), 45 deletions(-) diff --git a/cmd/themis-server/main.go b/cmd/themis-server/main.go index a118846..8b60574 100644 --- a/cmd/themis-server/main.go +++ b/cmd/themis-server/main.go @@ -20,6 +20,8 @@ import ( _ "github.com/mattn/go-sqlite3" "github.com/rs/zerolog" "github.com/rs/zerolog/log" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/sdk/resource" sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/trace" @@ -44,7 +46,7 @@ var ( gen = correlation.NewGenerator(seq) ) -type Handler func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) +type Handler func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) error func main() { log.Info().Msg("startup.") @@ -228,7 +230,7 @@ func main() { }, } handlers := map[string]Handler{ - "info": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { + "info": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) error { uptime, err := themis.Uptime(ctx) if err != nil { err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{ @@ -238,10 +240,9 @@ func main() { }, }) if err != nil { - log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") + return fmt.Errorf("failed to respond to interaction: %w", err) } - log.Error().Ctx(ctx).Err(err).Msg("failed to get server uptime") - return + return fmt.Errorf("failed to get server uptime: %w", err) } claimCount, uniquePlayers, err := store.CountClaims(ctx) @@ -960,57 +961,50 @@ func serve(address string) error { } func withLogging(name string, h Handler) Handler { - return func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { + return func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) error { ctx, span := tracer.Start(ctx, "discord-command") defer span.End() start := time.Now() logCommandInvocation(ctx, name, s, i) - h(ctx, s, i) - debugCommandCompletion(ctx, name, time.Since(start), s, i) + err := h(ctx, s, i) + debugCommandCompletion(ctx, name, time.Since(start), err, s, i) + return nil } } func logCommandInvocation(ctx context.Context, name string, s *discordgo.Session, i *discordgo.InteractionCreate) { - log.Info(). - Ctx(ctx). - Str("userid", i.Member.User.ID). - Str("username", i.Member.User.Username). - Str("command", name). - Str("params", func() string { - p := make([]string, 0, len(i.ApplicationCommandData().Options)) - for _, o := range i.ApplicationCommandData().Options { - sb := strings.Builder{} - sb.WriteString(o.Name) - sb.WriteRune('=') - - switch o.Type { - case discordgo.ApplicationCommandOptionSubCommand, discordgo.ApplicationCommandOptionSubCommandGroup: - panic("unreachable") - case discordgo.ApplicationCommandOptionString: - sb.WriteString(o.StringValue()) - case discordgo.ApplicationCommandOptionInteger: - sb.WriteString(fmt.Sprint(o.IntValue())) - case discordgo.ApplicationCommandOptionBoolean: - sb.WriteString(fmt.Sprint(o.BoolValue())) - default: - sb.WriteString("[unsupported type]") - } - p = append(p, sb.String()) - } - return strings.Join(p, ", ") - }()). - Msg("command invoked") + span := trace.SpanFromContext(ctx) + span.SetAttributes( + attribute.String("user_id", i.Member.User.ID), + attribute.String("username", i.Member.User.Username), + attribute.String("command_name", name), + ) + + for _, o := range i.ApplicationCommandData().Options { + switch o.Type { + case discordgo.ApplicationCommandOptionSubCommand, discordgo.ApplicationCommandOptionSubCommandGroup: + panic("unreachable") + case discordgo.ApplicationCommandOptionString: + span.SetAttributes(attribute.String(fmt.Sprintf("command_option.%s", o.Name), o.StringValue())) + case discordgo.ApplicationCommandOptionInteger: + span.SetAttributes(attribute.Int64(fmt.Sprintf("command_option.%s", o.Name), o.IntValue())) + case discordgo.ApplicationCommandOptionBoolean: + span.SetAttributes(attribute.Bool(fmt.Sprintf("command_option.%s", o.Name), o.BoolValue())) + default: + span.SetAttributes(attribute.String(fmt.Sprintf("command_option.%s", o.Name), "unsupported_type")) + } + } + + log.Info().Ctx(ctx).Msg("command invoked") } -func debugCommandCompletion(ctx context.Context, name string, dur time.Duration, s *discordgo.Session, i *discordgo.InteractionCreate) { - log.Info(). - Ctx(ctx). - Str("userid", i.Member.User.ID). - Str("username", i.Member.User.Username). - Str("command", name). - Dur("latency_ms", dur). - Msg("command completed") +func debugCommandCompletion(ctx context.Context, name string, dur time.Duration, err error, s *discordgo.Session, i *discordgo.InteractionCreate) { + span := trace.SpanFromContext(ctx) + if err != nil { + span.SetStatus(codes.Error, err.Error()) + } + log.Info().Ctx(ctx).Dur("latency_ms", dur).Msg("command completed") } func min(a, b int) int {