From 5cbaff0820b5b39a302e378a9e221b6bfff3d292 Mon Sep 17 00:00:00 2001 From: William Perron Date: Sun, 17 Dec 2023 16:26:13 -0500 Subject: [PATCH] improve logging, use console writer --- absences.go | 5 +++ audit_log.go | 2 ++ cmd/themis-server/main.go | 65 +++++++++++++++++++++++++++++++++------ conflicts.go | 3 ++ fmt.go | 6 ++++ notify.go | 10 ++++++ store.go | 22 +++++++++++++ uptime_linux.go | 3 ++ 8 files changed, 106 insertions(+), 10 deletions(-) diff --git a/absences.go b/absences.go index 63a01cc..2596bfd 100644 --- a/absences.go +++ b/absences.go @@ -4,10 +4,13 @@ import ( "context" "fmt" "time" + + "github.com/rs/zerolog/log" ) func (s *Store) AddAbsence(ctx context.Context, session time.Time, userId string) error { if session.Weekday() != time.Monday { + log.Debug().Msg(fmt.Sprintf("%s is not a monday", session)) return fmt.Errorf("not a monday") } @@ -36,6 +39,7 @@ func (s *Store) AddAbsence(ctx context.Context, session time.Time, userId string } func (s *Store) GetAbsentees(ctx context.Context, session time.Time) ([]string, error) { + log.Debug().Time("session", session).Msg("getting list of absentees") tx, err := s.db.Begin() if err != nil { return nil, fmt.Errorf("failed to begin transaction: %w", err) @@ -70,6 +74,7 @@ func (s *Store) GetAbsentees(ctx context.Context, session time.Time) ([]string, type Schedule map[string][]string func (s *Store) GetSchedule(ctx context.Context, from, to time.Time) (Schedule, error) { + log.Debug().Time("from", from).Time("to", to).Msg("getting next sessions schedule") schedule := make(Schedule) initSchedule(schedule, from, to) diff --git a/audit_log.go b/audit_log.go index 4a2c6d3..63b9eb2 100644 --- a/audit_log.go +++ b/audit_log.go @@ -60,6 +60,7 @@ type AuditableEvent struct { // used in a defered statement on functions that write to the database. func (s *Store) Audit(ev *AuditableEvent) { if ev.err == nil { + log.Debug().Str("event_type", ev.eventType.String()).Str("userid", ev.userId).Msg("recording audit log") ctx := context.Background() tx, err := s.db.Begin() @@ -87,6 +88,7 @@ type AuditEvent struct { } func (s *Store) LastOf(ctx context.Context, t EventType) (AuditEvent, error) { + log.Debug().Str("event_type", t.String()).Msg("finding last audit log") stmt, err := s.db.PrepareContext(ctx, `SELECT id, userid, event_type, ts FROM audit_log WHERE event_type = ? ORDER BY ts DESC LIMIT 1`) if err != nil { return AuditEvent{}, fmt.Errorf("failed to get last event of type %s: %w", t.String(), err) diff --git a/cmd/themis-server/main.go b/cmd/themis-server/main.go index 32529ed..8380606 100644 --- a/cmd/themis-server/main.go +++ b/cmd/themis-server/main.go @@ -17,6 +17,7 @@ import ( "github.com/bwmarrin/discordgo" _ "github.com/mattn/go-sqlite3" + "github.com/rs/zerolog" "github.com/rs/zerolog/log" "go.wperron.io/themis" @@ -27,7 +28,8 @@ const ( ) var ( - dbFile = flag.String("db", "", "SQlite database file path") + dbFile = flag.String("db", "", "SQlite database file path.") + debug = flag.Bool("debug", false, "Set log level to DEBUG.") store *themis.Store ) @@ -40,6 +42,21 @@ func main() { flag.Parse() + zerolog.SetGlobalLevel(zerolog.InfoLevel) + if *debug { + zerolog.SetGlobalLevel(zerolog.DebugLevel) + } + log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stdout}) + + log.Info().Msg("startup.") + + go func() { + if err := serve(":8080"); err != nil { + log.Error().Err(err).Msg("failed to serve requests") + } + cancel() + }() + err := touchDbFile(*dbFile) if err != nil { log.Fatal().Err(err).Msg("failed to touch database file") @@ -185,6 +202,7 @@ func main() { } handlers := map[string]Handler{ "info": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + logCommandInvocation("info", s, i) uptime, err := themis.Uptime() if err != nil { log.Error().Err(err).Msg("failed to get server uptime") @@ -224,6 +242,7 @@ func main() { } }, "list-claims": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + logCommandInvocation("list-claims", s, i) claims, err := store.ListClaims(ctx) if err != nil { log.Error().Err(err).Msg("failed to list claims") @@ -255,6 +274,7 @@ func main() { } }, "claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + logCommandInvocation("claim", s, i) if i.Type == discordgo.InteractionApplicationCommandAutocomplete { handleClaimAutocomplete(ctx, store, s, i) return @@ -344,6 +364,7 @@ func main() { } }, "describe-claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + logCommandInvocation("describe-claim", s, i) id := i.ApplicationCommandData().Options[0] detail, err := store.DescribeClaim(ctx, int(id.IntValue())) if err != nil { @@ -376,6 +397,7 @@ func main() { } }, "delete-claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + logCommandInvocation("delete-claim", s, i) id := i.ApplicationCommandData().Options[0] userId := i.Member.User.ID err := store.DeleteClaim(ctx, int(id.IntValue()), userId) @@ -407,6 +429,7 @@ func main() { } }, "flush": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + logCommandInvocation("flush", s, i) if err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{ Type: discordgo.InteractionResponseModal, Data: &discordgo.InteractionResponseData{ @@ -434,6 +457,7 @@ func main() { } }, "query": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + 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") @@ -468,6 +492,7 @@ func main() { } }, "schedule": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + 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 { @@ -512,6 +537,7 @@ func main() { } }, "absent": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + logCommandInvocation("absent", s, i) var rawDate string if len(i.ApplicationCommandData().Options) == 0 { rawDate = themis.NextMonday().Format(time.DateOnly) @@ -586,8 +612,11 @@ func main() { } defer discord.Close() - registeredCommands := make([]*discordgo.ApplicationCommand, len(commands)) + total := len(commands) + registeredCommands := make([]*discordgo.ApplicationCommand, total) + log.Debug().Int("total", total).Msg("registering commands with Discord") for i, c := range commands { + log.Debug().Msg(fmt.Sprintf("registering command %d of %d", i+1, total)) command, err := discord.ApplicationCommandCreate(appId, guildId, c) if err != nil { log.Fatal().Err(err).Msg("failed to register command") @@ -597,14 +626,8 @@ func main() { log.Info().Int("count", len(registeredCommands)).Msg("registered commands") - go func() { - if err := serve(":8080"); err != nil { - log.Error().Err(err).Msg("failed to serve requests") - } - cancel() - }() - go notifier.NotifyFunc(ctx, func() { + log.Info().Msg("sending weekly reminder") absentees, err := store.GetAbsentees(ctx, themis.NextMonday()) if err != nil { log.Error().Err(err).Msg("failed to get absentees for next session") @@ -632,7 +655,9 @@ func main() { <-ctx.Done() log.Info().Msg("context cancelled, exiting") - for _, c := range registeredCommands { + log.Debug().Int("total", total).Msg("deregistering commands with Discord") + for i, c := range registeredCommands { + log.Debug().Msg(fmt.Sprintf("registering command %d of %d", i+1, total)) err = discord.ApplicationCommandDelete(appId, guildId, c.ID) if err != nil { log.Error().Err(err).Msg("failed to deregister commands") @@ -643,6 +668,7 @@ func main() { } func touchDbFile(path string) error { + log.Debug().Str("path", path).Msg("touching database file") f, err := os.Open(path) if err != nil { if errors.Is(err, os.ErrNotExist) { @@ -674,6 +700,7 @@ func registerHandlers(sess *discordgo.Session, handlers map[string]Handler) { if strings.HasPrefix(i.ModalSubmitData().CustomID, "modals_flush_") { sub := i.ModalSubmitData().Components[0].(*discordgo.ActionsRow).Components[0].(*discordgo.TextInput).Value sub = strings.ToLower(sub) + log.Debug().Str("value", sub).Msg("flush modal submitted") if sub == "y" || sub == "ye" || sub == "yes" { err := store.Flush(context.Background(), i.Member.User.ID) msg := "Flushed all claims!" @@ -741,6 +768,7 @@ func formatClaimsTable(claims []themis.Claim) string { } func handleClaimAutocomplete(ctx context.Context, store *themis.Store, s *discordgo.Session, i *discordgo.InteractionCreate) { + log.Debug().Msg("getting autocomplete data for claim") opts := i.ApplicationCommandData().Options claimType, err := themis.ClaimTypeFromString(opts[0].StringValue()) if err != nil { @@ -762,6 +790,8 @@ func handleClaimAutocomplete(ctx context.Context, store *themis.Store, s *discor }) } + log.Debug().Int("len", len(choices)).Msg("found autocomplete suggestions") + if err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{ Type: discordgo.InteractionApplicationCommandAutocompleteResult, Data: &discordgo.InteractionResponseData{ @@ -780,6 +810,21 @@ func serve(address string) error { return http.ListenAndServe(address, nil) } +func logCommandInvocation(name string, s *discordgo.Session, i *discordgo.InteractionCreate) { + log.Info(). + 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 { + p = append(p, o.Name+"="+o.StringValue()) + } + return strings.Join(p, ", ") + }()). + Msg("command invoked") +} + func min(a, b int) int { if a < b { return a diff --git a/conflicts.go b/conflicts.go index 7448192..a02433a 100644 --- a/conflicts.go +++ b/conflicts.go @@ -3,6 +3,8 @@ package themis import ( "context" "fmt" + + "github.com/rs/zerolog/log" ) type Conflict struct { @@ -38,6 +40,7 @@ const conflictQuery string = `SELECT name, player, claim_type, val, id FROM ( );` func (s *Store) FindConflicts(ctx context.Context, userId, name string, claimType ClaimType) ([]Conflict, error) { + log.Debug().Stringer("claim_type", claimType).Str("userid", userId).Msg("searching for potential conflicts") stmt, err := s.db.PrepareContext(ctx, fmt.Sprintf(conflictQuery, claimTypeToColumn[claimType])) if err != nil { return nil, fmt.Errorf("failed to prepare conflicts query: %w", err) diff --git a/fmt.go b/fmt.go index fa090e8..29a28db 100644 --- a/fmt.go +++ b/fmt.go @@ -4,6 +4,8 @@ import ( "database/sql" "fmt" "strings" + + "github.com/rs/zerolog/log" ) func FormatRows(rows *sql.Rows) (string, error) { @@ -14,6 +16,8 @@ func FormatRows(rows *sql.Rows) (string, error) { return "", fmt.Errorf("failed to get rows columns: %w", err) } + log.Debug().Int("columns", len(cols)).Msg("formatting sql rows to markdown table") + c := make([]string, len(cols)) for i := range c { c[i] = " %-*s " @@ -44,6 +48,8 @@ func FormatRows(rows *sql.Rows) (string, error) { } } + log.Debug().Int("rows", len(scanned)).Ints("lengths", lengths).Msg("scanned rows and extracted max column lengths") + // Write column names curr := make([]any, 0, 2*len(cols)) for i := range lengths { diff --git a/notify.go b/notify.go index f0eb230..a3c59ff 100644 --- a/notify.go +++ b/notify.go @@ -4,6 +4,8 @@ import ( "context" "fmt" "time" + + "github.com/rs/zerolog/log" ) var loc *time.Location @@ -34,12 +36,16 @@ func (n *Notifier) Start(ctx context.Context) { panic("failed to parse next monday notif time. this is likely a bug.") } + log.Debug().Time("next", t).Msg("starting notifier instance") + first := time.NewTimer(time.Until(t)) <-first.C select { case <-ctx.Done(): + log.Debug().Msg("context deadline exceeded, exiting notifier") return default: + log.Debug().Msg("notifier tick") n.c <- struct{}{} } @@ -47,8 +53,10 @@ func (n *Notifier) Start(ctx context.Context) { for { select { case <-ctx.Done(): + log.Debug().Msg("context deadline exceeded, exiting notifier") return case <-ticker.C: + log.Debug().Msg("notifier tick") n.c <- struct{}{} } time.Sleep(time.Second) @@ -59,8 +67,10 @@ func (n *Notifier) NotifyFunc(ctx context.Context, f func()) { for { select { case <-ctx.Done(): + log.Debug().Msg("context deadline exceeded, exiting notify func") return case <-n.c: + log.Debug().Msg("tick received, notifying function") f() } time.Sleep(time.Second) diff --git a/store.go b/store.go index 594d162..b962879 100644 --- a/store.go +++ b/store.go @@ -13,6 +13,7 @@ import ( "github.com/golang-migrate/migrate/v4/database/sqlite3" "github.com/golang-migrate/migrate/v4/source/iofs" _ "github.com/mattn/go-sqlite3" + "github.com/rs/zerolog/log" ) //go:embed migrations/*.sql @@ -23,6 +24,7 @@ type Store struct { } func NewStore(conn string) (*Store, error) { + log.Debug().Str("connection_string", conn).Msg("opening sqlite3 database") db, err := sql.Open("sqlite3", conn) if err != nil { return nil, fmt.Errorf("failed to open database: %w", err) @@ -43,6 +45,12 @@ func NewStore(conn string) (*Store, error) { return nil, fmt.Errorf("failed to initialize db migrate: %w", err) } + ver, dirty, err := m.Version() + if err != nil { + return nil, fmt.Errorf("failed to get database migration version: %w", err) + } + + log.Debug().Uint("current_version", ver).Bool("dirty", dirty).Msg("running database migrations") err = m.Up() if err != nil && !errors.Is(err, migrate.ErrNoChange) { return nil, fmt.Errorf("failed to roll up migrations: %w", err) @@ -54,10 +62,17 @@ func NewStore(conn string) (*Store, error) { } func (s *Store) Close() error { + log.Debug().Msg("closing database") return s.db.Close() } func (s *Store) Claim(ctx context.Context, userId, player, province string, claimType ClaimType) (int, error) { + log.Debug(). + Str("userid", userId). + Str("player", player). + Str("provice", province). + Stringer("claim_type", claimType). + Msg("inserting claim") audit := &AuditableEvent{ userId: userId, eventType: EventClaim, @@ -78,6 +93,7 @@ func (s *Store) Claim(ctx context.Context, userId, player, province string, clai } if len(conflicts) > 0 { + log.Debug().Int("len", len(conflicts)).Msg("found conflicts") audit.err = err return 0, ErrConflict{Conflicts: conflicts} } @@ -124,6 +140,7 @@ func (s *Store) Claim(ctx context.Context, userId, player, province string, clai } func (s *Store) ListAvailability(ctx context.Context, claimType ClaimType, search ...string) ([]string, error) { + log.Debug().Stringer("claim_type", claimType).Strs("search_terms", search).Msg("listing available entries") queryParams := []any{string(claimType)} queryPattern := `SELECT DISTINCT(provinces.%[1]s) FROM provinces LEFT JOIN claims ON provinces.%[1]s = claims.val AND claims.claim_type = ? @@ -158,6 +175,7 @@ func (s *Store) ListAvailability(ctx context.Context, claimType ClaimType, searc } func (s *Store) ListClaims(ctx context.Context) ([]Claim, error) { + log.Debug().Msg("listing all claims currently in database") stmt, err := s.db.PrepareContext(ctx, `SELECT id, player, claim_type, val FROM claims`) if err != nil { return nil, fmt.Errorf("failed to prepare query: %w", err) @@ -203,6 +221,7 @@ func (cd ClaimDetail) String() string { } func (s *Store) DescribeClaim(ctx context.Context, ID int) (ClaimDetail, error) { + log.Debug().Int("id", ID).Msg("describing claim") stmt, err := s.db.PrepareContext(ctx, `SELECT id, player, claim_type, val FROM claims WHERE id = ?`) if err != nil { return ClaimDetail{}, fmt.Errorf("failed to get claim: %w", err) @@ -252,6 +271,7 @@ func (s *Store) DescribeClaim(ctx context.Context, ID int) (ClaimDetail, error) } func (s *Store) DeleteClaim(ctx context.Context, ID int, userId string) error { + log.Debug().Str("userid", userId).Int("id", ID).Msg("deleting claim") audit := &AuditableEvent{ userId: userId, eventType: EventUnclaim, @@ -283,6 +303,7 @@ func (s *Store) DeleteClaim(ctx context.Context, ID int, userId string) error { } func (s *Store) CountClaims(ctx context.Context) (total, uniquePlayers int, err error) { + log.Debug().Msg("counting all claims and unique users") stmt, err := s.db.PrepareContext(ctx, "SELECT COUNT(1), COUNT(DISTINCT(userid)) FROM claims") if err != nil { return 0, 0, fmt.Errorf("failed to prepare query: %w", err) @@ -298,6 +319,7 @@ func (s *Store) CountClaims(ctx context.Context) (total, uniquePlayers int, err } func (s *Store) Flush(ctx context.Context, userId string) error { + log.Debug().Str("initiated_by", userId).Msg("flushing all currently help claims") audit := &AuditableEvent{ userId: userId, eventType: EventFlush, diff --git a/uptime_linux.go b/uptime_linux.go index 11f8f3c..0995f76 100644 --- a/uptime_linux.go +++ b/uptime_linux.go @@ -8,6 +8,8 @@ import ( "os" "strconv" "time" + + "github.com/rs/zerolog/log" ) // Uptime returns the time elapsed since the start of the current process ID. @@ -16,6 +18,7 @@ func Uptime() (time.Duration, error) { if err != nil { return 0, fmt.Errorf("failed to read uptime from OS: %w", err) } + log.Debug().Str("raw", string(raw)).Msg("reading /proc/uptime to get server up time") i := bytes.IndexRune(raw, ' ')