More log events

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

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("corrrect", mh.participantID, mh.teamID, cat, points)
-	mh.State.LogEvent(msg)
 
 	if err := mh.State.AwardPoints(mh.teamID, cat, points); err != nil {
 		return fmt.Errorf("Error awarding points: %s", err)

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 logstr(s string) string {
-func (s *State) LogEvent(msg 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
 }
 

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", "", "", "", 0)
-	s.LogEvent("moo 2")
+	s.LogEvent("moo 2", "", "", "", 0)
 
-	if msg := <-s.eventStream; msg != "moo" {
+	if msg := <-s.eventStream; msg != "init - - - 0" {
-		t.Error("Wrong message from event stream", msg)
+		t.Error("Wrong message from event stream:", msg)
 	}
-	if msg := <-s.eventStream; msg != "moo 2" {
+	if msg := <-s.eventStream; msg != "moo - - - 0" {
-		t.Error("Formatted event is wrong:", msg)
+		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 {
+	} else if events := strings.Split(string(eventLog), "\n"); len(events) != 3 {
-		t.Error("Wrong event log length:", len(eventLog))
+		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")
 	}
 }

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.