From 0a9cc8d7e066940592e03c038e00693171039ceb Mon Sep 17 00:00:00 2001 From: William Perron Date: Sun, 31 Dec 2023 13:41:02 -0500 Subject: [PATCH] add correlation IDs and propagate ctx --- absences.go | 8 +- audit_log.go | 13 +-- cmd/themis-server/main.go | 134 +++++++++++++++------------ conflicts.go | 2 +- correlation/compat/zerolog/compat.go | 16 ++++ correlation/correlation.go | 47 ++++++++++ correlation/correlation_test.go | 18 ++++ correlation/crypto.go | 19 ++++ correlation/math.go | 18 ++++ fmt.go | 7 +- go.mod | 8 +- go.sum | 23 +++-- store.go | 21 +++-- uptime_linux.go | 5 +- uptime_test.go | 3 +- 15 files changed, 239 insertions(+), 103 deletions(-) create mode 100644 correlation/compat/zerolog/compat.go create mode 100644 correlation/correlation.go create mode 100644 correlation/correlation_test.go create mode 100644 correlation/crypto.go create mode 100644 correlation/math.go diff --git a/absences.go b/absences.go index 2596bfd..f85f258 100644 --- a/absences.go +++ b/absences.go @@ -10,11 +10,11 @@ import ( 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)) + log.Debug().Ctx(ctx).Msg(fmt.Sprintf("%s is not a monday", session)) return fmt.Errorf("not a monday") } - defer s.Audit(&AuditableEvent{ + defer s.Audit(ctx, &AuditableEvent{ userId: userId, eventType: EventAbsence, }) @@ -39,7 +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") + log.Debug().Ctx(ctx).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) @@ -74,7 +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") + log.Debug().Ctx(ctx).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 2abce19..1c36572 100644 --- a/audit_log.go +++ b/audit_log.go @@ -58,24 +58,24 @@ type AuditableEvent struct { // Audit writes to the audit table, returns nothing because it is meant to be // used in a defered statement on functions that write to the database. -func (s *Store) Audit(ev *AuditableEvent) { +func (s *Store) Audit(ctx context.Context, ev *AuditableEvent) { if ev.err == nil { - log.Debug().Str("event_type", ev.eventType.String()).Str("userid", ev.userId).Msg("recording audit log") + log.Debug().Ctx(ctx).Str("event_type", ev.eventType.String()).Str("userid", ev.userId).Msg("recording audit log") ctx := context.Background() tx, err := s.db.Begin() if err != nil { - log.Error().Err(err).Msg("failed to start transaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to start transaction") } defer tx.Commit() //nolint:errcheck stmt, err := s.db.PrepareContext(ctx, "INSERT INTO audit_log (userid, event_type, ts) VALUES (?, ?, ?)") if err != nil { - log.Error().Err(err).Msg("failed to prepare audit log insert") + log.Error().Ctx(ctx).Err(err).Msg("failed to prepare audit log insert") } if _, err := stmt.ExecContext(ctx, ev.userId, ev.eventType.String(), time.Now()); err != nil { - log.Error().Err(err).Msg("failed to insert audit log") + log.Error().Ctx(ctx).Err(err).Msg("failed to insert audit log") } } } @@ -88,7 +88,8 @@ 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") + log.Debug().Ctx(ctx).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 178d5f2..477629f 100644 --- a/cmd/themis-server/main.go +++ b/cmd/themis-server/main.go @@ -21,6 +21,8 @@ import ( "github.com/rs/zerolog/log" "go.wperron.io/themis" + "go.wperron.io/themis/correlation" + zerologcompat "go.wperron.io/themis/correlation/compat/zerolog" ) const ( @@ -32,9 +34,11 @@ var ( debug = flag.Bool("debug", false, "Set log level to DEBUG.") store *themis.Store + seq = &correlation.CryptoRandSequencer{} + gen = correlation.NewGenerator(seq) ) -type Handler func(s *discordgo.Session, i *discordgo.InteractionCreate) +type Handler func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) func main() { log.Info().Msg("startup.") @@ -50,6 +54,7 @@ func main() { zerolog.SetGlobalLevel(zerolog.DebugLevel) } log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stdout}) + log.Logger = log.Logger.Hook(zerologcompat.CorrelationHook{}) zerolog.DurationFieldUnit = time.Millisecond go func() { @@ -209,8 +214,8 @@ func main() { }, } handlers := map[string]Handler{ - "info": func(s *discordgo.Session, i *discordgo.InteractionCreate) { - uptime, err := themis.Uptime() + "info": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { + uptime, err := themis.Uptime(ctx) if err != nil { err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{ Type: discordgo.InteractionResponseChannelMessageWithSource, @@ -219,9 +224,9 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed to get server uptime") + log.Error().Ctx(ctx).Err(err).Msg("failed to get server uptime") return } @@ -234,9 +239,9 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed to count claims") + log.Error().Ctx(ctx).Err(err).Msg("failed to count claims") return } @@ -251,9 +256,9 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed get last flush event") + log.Error().Ctx(ctx).Err(err).Msg("failed get last flush event") return } lastFlush = "never" @@ -268,10 +273,10 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "list-claims": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "list-claims": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { claims, err := store.ListClaims(ctx) if err != nil { err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{ @@ -281,9 +286,9 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed to list claims") + log.Error().Ctx(ctx).Err(err).Msg("failed to list claims") return } @@ -300,12 +305,12 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "claim": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { if i.Type == discordgo.InteractionApplicationCommandAutocomplete { - log.Debug().Msg("command type interaction autocomplete") + log.Debug().Ctx(ctx).Msg("command type interaction autocomplete") handleClaimAutocomplete(ctx, store, s, i) return } @@ -319,7 +324,7 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } return } @@ -333,9 +338,9 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Str("claim_type", opts[0].StringValue()).Msg("failed to parse claim") + log.Error().Ctx(ctx).Err(err).Str("claim_type", opts[0].StringValue()).Msg("failed to parse claim") return } name := opts[1].StringValue() @@ -365,7 +370,7 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } return } @@ -377,9 +382,9 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed to acquire claim") + log.Error().Ctx(ctx).Err(err).Msg("failed to acquire claim") return } @@ -390,10 +395,10 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "describe-claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "describe-claim": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { id := i.ApplicationCommandData().Options[0] detail, err := store.DescribeClaim(ctx, int(id.IntValue())) if err != nil { @@ -404,9 +409,9 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed to describe claim") + log.Error().Ctx(ctx).Err(err).Msg("failed to describe claim") return } @@ -423,10 +428,10 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "delete-claim": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "delete-claim": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { id := i.ApplicationCommandData().Options[0] userId := i.Member.User.ID err := store.DeleteClaim(ctx, int(id.IntValue()), userId) @@ -442,10 +447,10 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed to delete claim") + log.Error().Ctx(ctx).Err(err).Msg("failed to delete claim") return } @@ -456,10 +461,10 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "flush": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "flush": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { if err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{ Type: discordgo.InteractionResponseModal, Data: &discordgo.InteractionResponseData{ @@ -483,13 +488,13 @@ func main() { }, }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "query": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "query": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { 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 database") + log.Error().Ctx(ctx).Err(err).Msg("failed to open read-only copy of database") return } @@ -498,13 +503,13 @@ 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().Ctx(ctx).Err(err).Msg("failed to exec user-provided query") return } - fmtd, err := themis.FormatRows(rows) + fmtd, err := themis.FormatRows(ctx, rows) if err != nil { - log.Error().Err(err).Msg("failed to format rows") + log.Error().Ctx(ctx).Err(err).Msg("failed to format rows") return } @@ -519,10 +524,10 @@ func main() { Content: table, }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "schedule": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "schedule": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { // 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 { @@ -532,9 +537,9 @@ func main() { Content: "failed to get schedule, check logs for more info.", }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } - log.Error().Err(err).Msg("failed to get schedule") + log.Error().Ctx(ctx).Err(err).Msg("failed to get schedule") return } @@ -564,10 +569,10 @@ func main() { Content: sb.String(), }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "send-schedule": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "send-schedule": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { notifier.Send() if err := s.InteractionRespond(i.Interaction, &discordgo.InteractionResponse{ @@ -576,10 +581,10 @@ func main() { Content: "Done.", }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, - "absent": func(s *discordgo.Session, i *discordgo.InteractionCreate) { + "absent": func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { var rawDate string if len(i.ApplicationCommandData().Options) == 0 { rawDate = themis.NextMonday().Format(time.DateOnly) @@ -595,7 +600,7 @@ func main() { Content: "failed to parse provided date, make sure to use the YYYY-MM-DD format.", }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } return } @@ -607,7 +612,7 @@ func main() { Content: "The date must be some time in the future.", }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } return } @@ -619,7 +624,7 @@ func main() { Content: "The date you provided is not a Monday.", }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } // TODO(wperron) suggest Mondays before and after? return @@ -633,7 +638,7 @@ func main() { Content: "something went wrong recording your absence, check logs for more info.", }, }); err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } return } @@ -645,7 +650,7 @@ func main() { }, }) if err != nil { - log.Error().Err(err).Msg("failed to respond to interaction") + log.Error().Ctx(ctx).Err(err).Msg("failed to respond to interaction") } }, } @@ -735,11 +740,18 @@ func registerHandlers(sess *discordgo.Session, handlers map[string]Handler) { log.Info().Str("user_id", fmt.Sprintf("%s#%s", s.State.User.Username, s.State.User.Discriminator)).Msg("logged in") }) sess.AddHandler(func(s *discordgo.Session, i *discordgo.InteractionCreate) { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + ctx = context.WithValue(ctx, "correlation_id", gen.Next()) + switch i.Type { case discordgo.InteractionApplicationCommand: if h, ok := handlers[i.ApplicationCommandData().Name]; ok { - withLogging(i.ApplicationCommandData().Name, h)(s, i) + withLogging(i.ApplicationCommandData().Name, h)(ctx, s, i) } + // TODO(wperron) apply correlation IDs to the other interation types + // TODO(wperron) is it possible to correlate a modal submit or message + // component to the original interaction? case discordgo.InteractionModalSubmit: if strings.HasPrefix(i.ModalSubmitData().CustomID, "modals_flush_") { sub := i.ModalSubmitData().Components[0].(*discordgo.ActionsRow).Components[0].(*discordgo.TextInput).Value @@ -880,17 +892,18 @@ 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) { +func withLogging(name string, h Handler) Handler { + return func(ctx context.Context, s *discordgo.Session, i *discordgo.InteractionCreate) { start := time.Now() - logCommandInvocation(name, s, i) - f(s, i) - debugCommandCompletion(name, time.Since(start), s, i) + logCommandInvocation(ctx, name, s, i) + h(ctx, s, i) + debugCommandCompletion(ctx, name, time.Since(start), s, i) } } -func logCommandInvocation(name string, s *discordgo.Session, i *discordgo.InteractionCreate) { +func logCommandInvocation(ctx context.Context, name string, s *discordgo.Session, i *discordgo.InteractionCreate) { log.Info(). + Ctx(ctx). Str("userid", i.Member.User.ID). Str("username", i.Member.User.Username). Str("command", name). @@ -920,8 +933,9 @@ 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(). +func debugCommandCompletion(ctx context.Context, name string, dur time.Duration, s *discordgo.Session, i *discordgo.InteractionCreate) { + log.Info(). + Ctx(ctx). Str("userid", i.Member.User.ID). Str("username", i.Member.User.Username). Str("command", name). diff --git a/conflicts.go b/conflicts.go index a02433a..e0036f8 100644 --- a/conflicts.go +++ b/conflicts.go @@ -40,7 +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") + log.Debug().Ctx(ctx).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/correlation/compat/zerolog/compat.go b/correlation/compat/zerolog/compat.go new file mode 100644 index 0000000..985b0ae --- /dev/null +++ b/correlation/compat/zerolog/compat.go @@ -0,0 +1,16 @@ +package zerolog + +import ( + zl "github.com/rs/zerolog" + "go.wperron.io/themis/correlation" +) + +type CorrelationHook struct{} + +func (h CorrelationHook) Run(e *zl.Event, level zl.Level, msg string) { + ctx := e.GetCtx() + c := correlation.FromContext(ctx) + if c != nil { + e.Stringer("correlation_id", c) + } +} diff --git a/correlation/correlation.go b/correlation/correlation.go new file mode 100644 index 0000000..6e2c92b --- /dev/null +++ b/correlation/correlation.go @@ -0,0 +1,47 @@ +package correlation + +import ( + "context" + "encoding/hex" +) + +const Key string = "correlation_id" + +var Empty CorrelationID = CorrelationID{0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00} + +// Correlation ID is a byte array of length 16 +type CorrelationID []byte + +func (ci CorrelationID) String() string { + if ci == nil { + return hex.EncodeToString(Empty) + } + return hex.EncodeToString(ci) +} + +func FromContext(ctx context.Context) CorrelationID { + if v := ctx.Value("correlation_id"); v != nil { + if c, ok := v.(CorrelationID); ok { + return c + } + } + return nil +} + +type Sequencer interface { + Next() []byte +} + +type Generator struct { + seq Sequencer +} + +func NewGenerator(seq Sequencer) *Generator { + return &Generator{ + seq: seq, + } +} + +func (g *Generator) Next() CorrelationID { + return CorrelationID(g.seq.Next()) +} diff --git a/correlation/correlation_test.go b/correlation/correlation_test.go new file mode 100644 index 0000000..565ec3d --- /dev/null +++ b/correlation/correlation_test.go @@ -0,0 +1,18 @@ +package correlation + +import ( + "math/rand" + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestGeneratorNext(t *testing.T) { + rand.Seed(0) + seq := &MathRandSequencer{} + gen := NewGenerator(seq) + + assert.Equal(t, "0194fdc2fa2ffcc041d3ff12045b73c8", gen.Next().String()) + assert.Equal(t, "6e4ff95ff662a5eee82abdf44a2d0b75", gen.Next().String()) + assert.Equal(t, "fb180daf48a79ee0b10d394651850fd4", gen.Next().String()) +} diff --git a/correlation/crypto.go b/correlation/crypto.go new file mode 100644 index 0000000..7656e3c --- /dev/null +++ b/correlation/crypto.go @@ -0,0 +1,19 @@ +package correlation + +import "crypto/rand" + +type CryptoRandSequencer struct{} + +func (crs *CryptoRandSequencer) Next() []byte { + buf := make([]byte, 16) + read, err := rand.Read(buf) + if err != nil { + panic("not implemented") + } + + if read != 16 { + panic("todo") + } + + return buf +} diff --git a/correlation/math.go b/correlation/math.go new file mode 100644 index 0000000..1577416 --- /dev/null +++ b/correlation/math.go @@ -0,0 +1,18 @@ +package correlation + +import "math/rand" + +type MathRandSequencer struct{} + +func (mrs *MathRandSequencer) Next() []byte { + buf := make([]byte, 16) + read, err := rand.Read(buf) + if err != nil { + panic("not implemented") + } + + if read != 16 { + panic("todo") + } + return buf +} diff --git a/fmt.go b/fmt.go index 29a28db..d50b2ed 100644 --- a/fmt.go +++ b/fmt.go @@ -1,6 +1,7 @@ package themis import ( + "context" "database/sql" "fmt" "strings" @@ -8,7 +9,7 @@ import ( "github.com/rs/zerolog/log" ) -func FormatRows(rows *sql.Rows) (string, error) { +func FormatRows(ctx context.Context, rows *sql.Rows) (string, error) { sb := strings.Builder{} cols, err := rows.Columns() @@ -16,7 +17,7 @@ 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") + log.Debug().Ctx(ctx).Int("columns", len(cols)).Msg("formatting sql rows to markdown table") c := make([]string, len(cols)) for i := range c { @@ -48,7 +49,7 @@ func FormatRows(rows *sql.Rows) (string, error) { } } - log.Debug().Int("rows", len(scanned)).Ints("lengths", lengths).Msg("scanned rows and extracted max column lengths") + log.Debug().Ctx(ctx).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)) diff --git a/go.mod b/go.mod index 8e5e82f..e6522d9 100644 --- a/go.mod +++ b/go.mod @@ -6,7 +6,7 @@ require ( github.com/bwmarrin/discordgo v0.26.1 github.com/golang-migrate/migrate/v4 v4.16.2 github.com/mattn/go-sqlite3 v1.14.16 - github.com/rs/zerolog v1.28.0 + github.com/rs/zerolog v1.31.0 github.com/stretchr/testify v1.8.1 ) @@ -15,11 +15,11 @@ require ( github.com/gorilla/websocket v1.4.2 // indirect github.com/hashicorp/errwrap v1.1.0 // indirect github.com/hashicorp/go-multierror v1.1.1 // indirect - github.com/mattn/go-colorable v0.1.12 // indirect - github.com/mattn/go-isatty v0.0.16 // indirect + github.com/mattn/go-colorable v0.1.13 // indirect + github.com/mattn/go-isatty v0.0.19 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect go.uber.org/atomic v1.7.0 // indirect golang.org/x/crypto v0.7.0 // indirect - golang.org/x/sys v0.8.0 // indirect + golang.org/x/sys v0.12.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 9eb4eca..dc668c5 100644 --- a/go.sum +++ b/go.sum @@ -1,6 +1,6 @@ github.com/bwmarrin/discordgo v0.26.1 h1:AIrM+g3cl+iYBr4yBxCBp9tD9jR3K7upEjl0d89FRkE= github.com/bwmarrin/discordgo v0.26.1/go.mod h1:NJZpH+1AfhIcyQsPeuBKsUtYrRnjkyu0kIVMCHkZtRY= -github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= +github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -16,19 +16,19 @@ github.com/hashicorp/go-multierror v1.1.1 h1:H5DkEtf6CXdFp0N0Em5UCwQpXMWke8IA0+l github.com/hashicorp/go-multierror v1.1.1/go.mod h1:iw975J/qwKPdAO1clOe2L8331t/9/fmwbPZ6JB6eMoM= github.com/lib/pq v1.10.2 h1:AqzbZs4ZoCBp+GtejcpCpcxM3zlSMx29dXbUSeVtJb8= github.com/lib/pq v1.10.2/go.mod h1:AlVN5x4E4T544tWzH6hKfbfQvm3HdbOxrmggDNAPY9o= -github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40= -github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4= -github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94= -github.com/mattn/go-isatty v0.0.16 h1:bq3VjFmv/sOjHtdEhmkEV4x1AJtvUvOJ2PFAZ5+peKQ= +github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= +github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA= +github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/mattn/go-sqlite3 v1.14.16 h1:yOQRA0RpS5PFz/oikGwBEqvAWhWg5ufRz4ETLjwpU1Y= github.com/mattn/go-sqlite3 v1.14.16/go.mod h1:2eHXhiwb8IkHr+BDWZGa96P6+rkvnG63S2DGjv9HUNg= github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= -github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= -github.com/rs/zerolog v1.28.0 h1:MirSo27VyNi7RJYP3078AA1+Cyzd2GB66qy3aUHvsWY= -github.com/rs/zerolog v1.28.0/go.mod h1:NILgTygv/Uej1ra5XxGf82ZFSLk58MFGAUS2o6usyD0= +github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.31.0 h1:FcTR3NnLWW+NnTwwhFWiJSZr4ECLpqCm6QsEnyvbV4A= +github.com/rs/zerolog v1.31.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo= @@ -44,11 +44,10 @@ golang.org/x/crypto v0.7.0 h1:AvwMYaRytfdeVt3u6mLaxYtErKYjxA2OXjJ1HHq6t3A= golang.org/x/crypto v0.7.0/go.mod h1:pYwdfH91IfpZVANVyUOhSIPZaFoJGxTFbZhFTx+dXZU= golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg= golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.8.0 h1:EBmGv8NaZBZTWvrbjNoL6HVt+IVy3QDQpJs7VRIw3tU= -golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.12.0 h1:CM0HF96J0hcLAwsHPJZjfdNzs0gftsLfgKt57wWHJ0o= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= diff --git a/store.go b/store.go index b962879..9802858 100644 --- a/store.go +++ b/store.go @@ -68,6 +68,7 @@ func (s *Store) Close() error { func (s *Store) Claim(ctx context.Context, userId, player, province string, claimType ClaimType) (int, error) { log.Debug(). + Ctx(ctx). Str("userid", userId). Str("player", player). Str("provice", province). @@ -77,7 +78,7 @@ func (s *Store) Claim(ctx context.Context, userId, player, province string, clai userId: userId, eventType: EventClaim, } - defer s.Audit(audit) + defer s.Audit(ctx, audit) tx, err := s.db.Begin() if err != nil { @@ -93,7 +94,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") + log.Debug().Ctx(ctx).Int("len", len(conflicts)).Msg("found conflicts") audit.err = err return 0, ErrConflict{Conflicts: conflicts} } @@ -140,7 +141,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") + log.Debug().Ctx(ctx).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 = ? @@ -175,7 +176,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") + log.Debug().Ctx(ctx).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) @@ -221,7 +222,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") + log.Debug().Ctx(ctx).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) @@ -271,12 +272,12 @@ 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") + log.Debug().Ctx(ctx).Str("userid", userId).Int("id", ID).Msg("deleting claim") audit := &AuditableEvent{ userId: userId, eventType: EventUnclaim, } - defer s.Audit(audit) + defer s.Audit(ctx, audit) stmt, err := s.db.PrepareContext(ctx, "DELETE FROM claims WHERE id = ? AND userid = ?") if err != nil { @@ -303,7 +304,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") + log.Debug().Ctx(ctx).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) @@ -319,12 +320,12 @@ 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") + log.Debug().Ctx(ctx).Str("initiated_by", userId).Msg("flushing all currently help claims") audit := &AuditableEvent{ userId: userId, eventType: EventFlush, } - defer s.Audit(audit) + defer s.Audit(ctx, audit) _, err := s.db.ExecContext(ctx, "DELETE FROM claims;") if err != nil { diff --git a/uptime_linux.go b/uptime_linux.go index 0995f76..c5e7509 100644 --- a/uptime_linux.go +++ b/uptime_linux.go @@ -4,6 +4,7 @@ package themis import ( "bytes" + "context" "fmt" "os" "strconv" @@ -13,12 +14,12 @@ import ( ) // Uptime returns the time elapsed since the start of the current process ID. -func Uptime() (time.Duration, error) { +func Uptime(ctx context.Context) (time.Duration, error) { raw, err := os.ReadFile("/proc/uptime") 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") + log.Debug().Ctx(ctx).Str("raw", string(raw)).Msg("reading /proc/uptime to get server up time") i := bytes.IndexRune(raw, ' ') diff --git a/uptime_test.go b/uptime_test.go index 5d24e8e..c9fb394 100644 --- a/uptime_test.go +++ b/uptime_test.go @@ -1,6 +1,7 @@ package themis import ( + "context" "runtime" "testing" "time" @@ -12,7 +13,7 @@ func TestUptime(t *testing.T) { if runtime.GOOS == "darwin" { t.Skip() } - uptime, err := Uptime() + uptime, err := Uptime(context.Background()) assert.NoError(t, err) assert.Greater(t, uptime, 100*time.Millisecond) }