refactor command logging middleware

cmd/themis-server/main.go

@@ -204,8 +204,6 @@ 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 {
 				err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
@@ -217,7 +215,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 get server uptime")
+				log.Error().Err(err).Msg("failed to get server uptime")
 				return
 			}
 
@@ -232,7 +230,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 count claims")
+				log.Error().Err(err).Msg("failed to count claims")
 				return
 			}
 
@@ -249,7 +247,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 get last flush event")
+					log.Error().Err(err).Msg("failed get last flush event")
 					return
 				}
 				lastFlush = "never"
@@ -266,11 +264,8 @@ 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 {
 				err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{
@@ -282,7 +277,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 list claims")
+				log.Error().Err(err).Msg("failed to list claims")
 				return
 			}
 
@@ -301,15 +296,11 @@ 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
 			}
 
@@ -324,7 +315,6 @@ func main() {
 				if err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
-				debugCommandCompletion("claim", time.Since(st), s, i)
 				return
 			}
 
@@ -339,7 +329,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")
+				log.Error().Err(err).Str("claim_type", opts[0].StringValue()).Msg("failed to parse claim")
 				return
 			}
 			name := opts[1].StringValue()
@@ -371,7 +361,6 @@ func main() {
 					if err != nil {
 						log.Error().Err(err).Msg("failed to respond to interaction")
 					}
-					debugCommandCompletion("claim", time.Since(st), s, i)
 					return
 				}
 
@@ -384,7 +373,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")
+				log.Error().Err(err).Msg("failed to acquire claim")
 				return
 			}
 
@@ -397,11 +386,8 @@ 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 {
@@ -414,7 +400,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 describe claim")
+				log.Error().Err(err).Msg("failed to describe claim")
 				return
 			}
 
@@ -433,11 +419,8 @@ 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
 			err := store.DeleteClaim(ctx, int(id.IntValue()), userId)
@@ -456,7 +439,7 @@ func main() {
 					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")
+				log.Error().Err(err).Msg("failed to delete claim")
 				return
 			}
 
@@ -469,11 +452,8 @@ 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,
 				Data: &discordgo.InteractionResponseData{
@@ -499,14 +479,11 @@ 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).Dur("latency_ms", time.Since(st)).Msg("failed to open read-only copy of database")
+				log.Error().Err(err).Msg("failed to open read-only copy of database")
 				return
 			}
 
@@ -515,13 +492,13 @@ func main() {
 			defer cancelDeadline()
 			rows, err := roDB.QueryContext(deadlined, q)
 			if err != nil {
-				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to exec user-provided query")
+				log.Error().Err(err).Msg("failed to exec user-provided query")
 				return
 			}
 
 			fmtd, err := themis.FormatRows(rows)
 			if err != nil {
-				log.Error().Err(err).Dur("latency_ms", time.Since(st)).Msg("failed to format rows")
+				log.Error().Err(err).Msg("failed to format rows")
 				return
 			}
 
@@ -538,11 +515,8 @@ 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 {
@@ -554,7 +528,7 @@ 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")
+				log.Error().Err(err).Msg("failed to get schedule")
 				return
 			}
 
@@ -586,11 +560,8 @@ 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 {
 				rawDate = themis.NextMonday().Format(time.DateOnly)
@@ -608,7 +579,6 @@ func main() {
 				}); err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
-				debugCommandCompletion("absent", time.Since(st), s, i)
 				return
 			}
 
@@ -621,7 +591,6 @@ func main() {
 				}); err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
-				debugCommandCompletion("absent", time.Since(st), s, i)
 				return
 			}
 
@@ -635,7 +604,6 @@ 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
 			}
 
@@ -649,7 +617,6 @@ func main() {
 				}); err != nil {
 					log.Error().Err(err).Msg("failed to respond to interaction")
 				}
-				debugCommandCompletion("absence", time.Since(st), s, i)
 				return
 			}
 
@@ -662,7 +629,6 @@ func main() {
 			if err != nil {
 				log.Error().Err(err).Msg("failed to respond to interaction")
 			}
-			debugCommandCompletion("absence", time.Since(st), s, i)
 		},
 	}
 
@@ -739,7 +705,7 @@ func registerHandlers(sess *discordgo.Session, handlers map[string]Handler) {
 		switch i.Type {
 		case discordgo.InteractionApplicationCommand:
 			if h, ok := handlers[i.ApplicationCommandData().Name]; ok {
-				h(s, i)
+				withLogging(i.ApplicationCommandData().Name, h)(s, i)
 			}
 		case discordgo.InteractionModalSubmit:
 			if strings.HasPrefix(i.ModalSubmitData().CustomID, "modals_flush_") {
@@ -855,6 +821,15 @@ func serve(address string) error {
 	return http.ListenAndServe(address, nil)
 }
 
+func withLogging(name string, f func(s *discordgo.Session, i *discordgo.InteractionCreate)) func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+	return func(s *discordgo.Session, i *discordgo.InteractionCreate) {
+		start := time.Now()
+		logCommandInvocation(name, s, i)
+		f(s, i)
+		debugCommandCompletion(name, time.Since(start), s, i)
+	}
+}
+
 func logCommandInvocation(name string, s *discordgo.Session, i *discordgo.InteractionCreate) {
 	log.Info().
 		Str("userid", i.Member.User.ID).