From b292db105048f9db7d40aa303cbae0ea9f2d6229 Mon Sep 17 00:00:00 2001 From: William Perron Date: Sat, 23 Dec 2023 17:36:54 -0500 Subject: [PATCH] refactor command logging middleware --- cmd/themis-server/main.go | 69 +++++++++++++-------------------------- 1 file changed, 22 insertions(+), 47 deletions(-) diff --git a/cmd/themis-server/main.go b/cmd/themis-server/main.go index 8c95329..cfc011f 100644 --- a/cmd/themis-server/main.go +++ b/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).