diff --git a/cmd/themis-server/main.go b/cmd/themis-server/main.go index 6cf921d..8c95329 100644 --- a/cmd/themis-server/main.go +++ b/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