improve logging, use console writer

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)
 

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)

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

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)

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 {

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)

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,

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, ' ')