From 5cb09066e2ab4ea62e2d7b2d6289b008ed0b639c Mon Sep 17 00:00:00 2001 From: Neale Pickett Date: Wed, 14 Oct 2020 18:20:49 -0600 Subject: [PATCH] More log events --- CHANGELOG.md | 5 +++ cmd/mothd/server.go | 11 +++++-- cmd/mothd/state.go | 32 ++++++++++++++++-- cmd/mothd/state_test.go | 24 ++++++++------ docs/logs.md | 72 +++++++++++++++++++++++++++++++++++++++++ 5 files changed, 129 insertions(+), 15 deletions(-) create mode 100644 docs/logs.md diff --git a/CHANGELOG.md b/CHANGELOG.md index dd173c2..018063a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,11 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [v4.1.0-pre] - Unreleased +### Added +- More log events +- [Log channels document](docs/logs.md) + ## [v4.0.0] - 2020-10-14 ### Fixed - Multiple bugs preventing production server from working properly diff --git a/cmd/mothd/server.go b/cmd/mothd/server.go index 0b35618..e7789e2 100644 --- a/cmd/mothd/server.go +++ b/cmd/mothd/server.go @@ -58,7 +58,7 @@ type StateProvider interface { TeamName(teamID string) (string, error) SetTeamName(teamID, teamName string) error AwardPoints(teamID string, cat string, points int) error - LogEvent(msg string) + LogEvent(event, participantID, teamID, cat string, points int, extra ...string) Maintainer } @@ -126,6 +126,11 @@ func (mh *MothRequestHandler) PuzzlesOpen(cat string, points int, path string) ( } } + // Log puzzle.json loads + if path == "puzzle.json" { + mh.State.LogEvent("load", "", "", "", 0) + } + return } @@ -140,11 +145,11 @@ func (mh *MothRequestHandler) CheckAnswer(cat string, points int, answer string) } } if !correct { + mh.State.LogEvent("wrong", mh.participantID, mh.teamID, cat, points) return fmt.Errorf("Incorrect answer") } - msg := fmt.Sprintf("GOOD %s %s %s %d", mh.participantID, mh.teamID, cat, points) - mh.State.LogEvent(msg) + mh.State.LogEvent("corrrect", mh.participantID, mh.teamID, cat, points) if err := mh.State.AwardPoints(mh.teamID, cat, points); err != nil { return fmt.Errorf("Error awarding points: %s", err) diff --git a/cmd/mothd/state.go b/cmd/mothd/state.go index ed10197..c861f00 100644 --- a/cmd/mothd/state.go +++ b/cmd/mothd/state.go @@ -113,6 +113,11 @@ func (s *State) updateEnabled() { if nextEnabled != s.Enabled { s.Enabled = nextEnabled log.Printf("Setting enabled=%v: %s", s.Enabled, why) + if s.Enabled { + s.LogEvent("enabled", "", "", "", 0, why) + } else { + s.LogEvent("disabled", "", "", "", 0, why) + } } } @@ -308,6 +313,7 @@ func (s *State) maybeInitialize() { if err := s.reopenEventLog(); err != nil { log.Fatal(err) } + s.LogEvent("init", "", "", "", 0) // Make sure various subdirectories exist s.Mkdir("points.tmp", 0755) @@ -351,7 +357,7 @@ func (s *State) maybeInitialize() { fmt.Fprintln(f, "# Times in the future are ignored.") fmt.Fprintln(f) fmt.Fprintln(f, "+", now) - fmt.Fprintln(f, "- 3019-10-31T00:00:00Z") + fmt.Fprintln(f, "- 2519-10-31T00:00:00Z") f.Close() } @@ -365,8 +371,28 @@ func (s *State) maybeInitialize() { } } -// LogEvent writes msg to the event log -func (s *State) LogEvent(msg string) { +func logstr(s string) string { + if s == "" { + return "-" + } + return s +} + +// LogEvent writes to the event log +func (s *State) LogEvent(event, participantID, teamID, cat string, points int, extra ...string) { + event = strings.ReplaceAll(event, " ", "-") + + msg := fmt.Sprintf( + "%s %s %s %s %d", + logstr(event), + logstr(participantID), + logstr(teamID), + logstr(cat), + points, + ) + for _, x := range extra { + msg = msg + " " + strings.ReplaceAll(x, " ", "-") + } s.eventStream <- msg } diff --git a/cmd/mothd/state_test.go b/cmd/mothd/state_test.go index c05bd3b..621df07 100644 --- a/cmd/mothd/state_test.go +++ b/cmd/mothd/state_test.go @@ -124,14 +124,17 @@ func TestState(t *testing.T) { func TestStateEvents(t *testing.T) { s := NewTestState() - s.LogEvent("moo") - s.LogEvent("moo 2") + s.LogEvent("moo", "", "", "", 0) + s.LogEvent("moo 2", "", "", "", 0) - if msg := <-s.eventStream; msg != "moo" { - t.Error("Wrong message from event stream", msg) + if msg := <-s.eventStream; msg != "init - - - 0" { + t.Error("Wrong message from event stream:", msg) } - if msg := <-s.eventStream; msg != "moo 2" { - t.Error("Formatted event is wrong:", msg) + if msg := <-s.eventStream; msg != "moo - - - 0" { + t.Error("Wrong message from event stream:", msg) + } + if msg := <-s.eventStream; msg != "moo-2 - - - 0" { + t.Error("Wrong message from event stream:", msg) } } @@ -230,7 +233,7 @@ func TestStateMaintainer(t *testing.T) { t.Error("Team ID too short:", teamID) } - s.LogEvent("Hello!") + s.LogEvent("Hello!", "", "", "", 0) if len(s.PointsLog()) != 0 { t.Error("Points log is not empty") @@ -255,7 +258,10 @@ func TestStateMaintainer(t *testing.T) { eventLog, err := afero.ReadFile(s.Fs, "event.log") if err != nil { t.Error(err) - } else if len(eventLog) != 18 { - t.Error("Wrong event log length:", len(eventLog)) + } else if events := strings.Split(string(eventLog), "\n"); len(events) != 3 { + t.Log("Events:", events) + t.Error("Wrong event log length:", len(events)) + } else if events[2] != "" { + t.Error("Event log didn't end with newline") } } diff --git a/docs/logs.md b/docs/logs.md new file mode 100644 index 0000000..15836c3 --- /dev/null +++ b/docs/logs.md @@ -0,0 +1,72 @@ +Moth Logs +======= + +Moth has multiple log channels: + +`points.log` +: the points log, used by server and scoreboard + +`events.log` +: significant events, used to do manual analysis after an event + +`stdout` +: HTTP server access + +`stderr` +: warnings and errors + + +`points.log` format +---------------------- + +The points log is a space-separated file. +Each line has four fields: + +| `timestamp` | `teamID` | `category` | `points` | +| --- | --- | --- | --- | +| int | string | string | int | +| Unix epoch | Team's unique ID | Name of category | Points awarded | + + +### Example + +``` +1602702696 2255 nocode 1 +1602702705 2255 sequence 1 +1602702787 2255 nocode 2 +1602702831 2255 sequence 2 +1602702839 9458 nocode 3 +1602702896 2255 sequence 8 +1602702900 9458 nocode 4 +1602702913 2255 sequence 16 +``` + +`events.log` format +---------------------- + +The events log is a space-separated file. +Each line has six fields minimum: + +| `timestamp` | `event` | `participantID` | `teamID` | `category` | `points` | `extra`... | +| --- | --- | --- | --- | --- | --- | --- | +| int | string | string | string | string | int | string... | +| Unix epoch | Event type | Team's unique ID| Participant's (hopefully) unique ID | Name of category, if any | Points awarded, if any | Additional fields, if any | + +Fields after `points` contain extra fields associated with the event. + +### Example + +``` +1602716345 init - - - - 0 +1602716349 load 2255 player5 sequence 1 +1602716450 load 4824 player3 sequence 1 +1602716359 correct 2255 player5 sequence 1 +1602716423 wrong 4824 player3 sequence 1 +1602716428 correct 4824 player3 sequence 1 +1602716530 correct 4824 player3 sequence 1 +1602716546 abduction 4824 player3 - 0 alien FM1490 +``` + +The final entry is a made-up "alien abduction" entry, +since at the time of writing, +we didn't have any actual events that wrote extra fields.