wip: refactor command logging and tracing

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 {