add debug info for each command with total latency

cmd/themis-server/main.go

@@ -204,10 +204,10 @@ func main() {
 	}
 	handlers := map[string]Handler{
 		"info": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("info", s, i)
 			uptime, err := themis.Uptime()
 			if err != nil {
-				log.Error().Err(err).Msg("failed to get server uptime")
 				err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -217,11 +217,12 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to get server uptime")
+				return
 			}
 
 			claimCount, uniquePlayers, err := store.CountClaims(ctx)
 			if err != nil {
-				log.Error().Err(err).Msg("failed to count claims")
 				err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -231,13 +232,14 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to count claims")
+				return
 			}
 
 			ev, err := store.LastOf(ctx, themis.EventFlush)
 			var lastFlush string
 			if err != nil {
 				if err != themis.ErrNever {
-					log.Error().Err(err).Msg("failed get last flush event")
 					err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 						Type: discordgo.InteractionResponseChannelMessageWithSource,
 						Data: &discordgo.InteractionResponseData{
@@ -247,6 +249,8 @@ func main() {
 					if err != nil {
 						log.Error().Err(err).Msg("failed to respond to interaction")
 					}
+					log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed get last flush event")
+					return
 				}
 				lastFlush = "never"
 			} else {
@@ -262,12 +266,13 @@ func main() {
 			if err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("info", time.Since(st), s, i)
 		},
 		"list-claims": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("list-claims", s, i)
 			claims, err := store.ListClaims(ctx)
 			if err != nil {
-				log.Error().Err(err).Msg("failed to list claims")
 				err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -277,6 +282,8 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to list claims")
+				return
 			}
 
 			sb := strings.Builder{}
@@ -294,11 +301,15 @@ func main() {
 			if err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("list-claims", time.Since(st), s, i)
 		},
 		"claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("claim", s, i)
 			if i.Type == discordgo.InteractionApplicationCommandAutocomplete {
+				log.Debug().Msg("command type interaction autocomplete")
 				handleClaimAutocomplete(ctx, store, s, i)
+				debugCommandCompletion("claim", time.Since(st), s, i)
 				return
 			}
 
@@ -313,12 +324,12 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				debugCommandCompletion("claim", time.Since(st), s, i)
 				return
 			}
 
 			claimType, err := themis.ClaimTypeFromString(opts[0].StringValue())
 			if err != nil {
-				log.Error().Err(err).Str("claim_type", opts[0].StringValue()).Msg("failed to parse claim")
 				err = s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -328,6 +339,7 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Str("claim_type", opts[0].StringValue()).Msg("failed to parse claim")
 				return
 			}
 			name := opts[1].StringValue()
@@ -359,10 +371,10 @@ func main() {
 					if err != nil {
 						log.Error().Err(err).Msg("failed to respond to interaction")
 					}
+					debugCommandCompletion("claim", time.Since(st), s, i)
 					return
 				}
 
-				log.Error().Err(err).Msg("failed to acquire claim")
 				err = s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -372,6 +384,7 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to acquire claim")
 				return
 			}
 
@@ -384,13 +397,14 @@ func main() {
 			if err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("claim", time.Since(st), s, i)
 		},
 		"describe-claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("describe-claim", s, i)
 			id := i.ApplicationCommandData().Options[0]
 			detail, err := store.DescribeClaim(ctx, int(id.IntValue()))
 			if err != nil {
-				log.Error().Err(err).Msg("failed to describe claim")
 				err = s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -400,6 +414,8 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to describe claim")
+				return
 			}
 
 			sb := strings.Builder{}
@@ -417,8 +433,10 @@ func main() {
 			if err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("describe-claim", time.Since(st), s, i)
 		},
 		"delete-claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("delete-claim", s, i)
 			id := i.ApplicationCommandData().Options[0]
 			userId := i.Member.User.ID
@@ -428,7 +446,6 @@ func main() {
 				if errors.Is(err, themis.ErrNoSuchClaim) {
 					msg = fmt.Sprintf("Claim #%d not found for %s", id.IntValue(), i.Member.Nick)
 				}
-				log.Error().Err(err).Msg("failed to delete claim")
 				err = s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -438,6 +455,9 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to delete claim")
+				return
 			}
 
 			err = s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
@@ -449,8 +469,10 @@ func main() {
 			if err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("delete-claim", time.Since(st), s, i)
 		},
 		"flush": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("flush", s, i)
 			if err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 				Type: discordgo.InteractionResponseModal,
@@ -477,12 +499,15 @@ func main() {
 			}); err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("flush", time.Since(st), s, i)
 		},
 		"query": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("query", s, i)
 			roDB, err := sql.Open("sqlite3", fmt.Sprintf("file:%s?cache=private&mode=ro", *dbFile))
 			if err != nil {
-				log.Error().Err(err).Msg("failed to open read-only copy of databse")
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to open read-only copy of database")
+				return
 			}
 
 			q := i.ApplicationCommandData().Options[0].StringValue()
@@ -490,13 +515,14 @@ func main() {
 			defer cancelDeadline()
 			rows, err := roDB.QueryContext(deadlined, q)
 			if err != nil {
-				log.Error().Err(err).Msg("failed to exec user-provided query")
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to exec user-provided query")
 				return
 			}
 
 			fmtd, err := themis.FormatRows(rows)
 			if err != nil {
-				log.Error().Err(err).Msg("failed to format rows")
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to format rows")
+				return
 			}
 
 			// 2000 is a magic number here, it's the character limit for a discord
@@ -512,13 +538,14 @@ func main() {
 			}); err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("query", time.Since(st), s, i)
 		},
 		"schedule": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("schedule", s, i)
 			// get schedule from now to 4 mondays into the future
 			sched, err := store.GetSchedule(ctx, themis.NextMonday(), themis.NextMonday().Add(4*7*24*time.Hour))
 			if err != nil {
-				log.Error().Err(err).Msg("failed to get schedule")
 				if err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
 					Type: discordgo.InteractionResponseChannelMessageWithSource,
 					Data: &discordgo.InteractionResponseData{
@@ -527,6 +554,8 @@ func main() {
 				}); err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to get schedule")
+				return
 			}
 
 			sb := strings.Builder{}
@@ -557,8 +586,10 @@ func main() {
 			}); err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("schedule", time.Since(st), s, i)
 		},
 		"absent": func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+			st := time.Now()
 			logCommandInvocation("absent", s, i)
 			var rawDate string
 			if len(i.ApplicationCommandData().Options) == 0 {
@@ -577,6 +608,8 @@ func main() {
 				}); err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				debugCommandCompletion("absent", time.Since(st), s, i)
+				return
 			}
 
 			if date.Before(time.Now()) {
@@ -588,6 +621,8 @@ func main() {
 				}); err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				debugCommandCompletion("absent", time.Since(st), s, i)
+				return
 			}
 
 			if date.Weekday() != time.Monday {
@@ -600,6 +635,8 @@ func main() {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
 				// TODO(wperron) suggest Mondays before and after?
+				debugCommandCompletion("absent", time.Since(st), s, i)
+				return
 			}
 
 			userId := i.Member.User.ID
@@ -612,6 +649,8 @@ func main() {
 				}); err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
+				debugCommandCompletion("absence", time.Since(st), s, i)
+				return
 			}
 
 			err = s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
@@ -623,6 +662,7 @@ func main() {
 			if err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
+			debugCommandCompletion("absence", time.Since(st), s, i)
 		},
 	}
 
@@ -830,6 +870,15 @@ func logCommandInvocation(name string, s *discordgo.Session, i *discordgo.Intera
 		Msg("command invoked")
 }
 
+func debugCommandCompletion(name string, dur time.Duration, s *discordgo.Session, i *discordgo.InteractionCreate) {
+	log.Debug().
+		Str("userid", i.Member.User.ID).
+		Str("username", i.Member.User.Username).
+		Str("command", name).
+		Dur("latency_ms", dur).
+		Msg("command completed")
+}
+
 func min(a, b int) int {
 	if a < b {
 		return a