Backport event logging from v4

CHANGELOG.md

@@ -5,6 +5,8 @@ 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).
 
 ## [Unreleased]
+### Added
+- Backport event logging from v4
 
 ## [v3.5.1] - 2020-03-16
 ### Fixed

docs/logs.md

@@ -0,0 +1,81 @@
+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. 
+
+### Event types
+
+These may change in the future.
+
+* init: startup of server
+* disabled: points accumulation disabled for this maintenance run
+* wrong: wrong answer submitted
+* correct: correct answer submitted
+
+### 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.

src/handlers.go

@@ -98,6 +98,7 @@ func (ctx *Instance) registerHandler(w http.ResponseWriter, req *http.Request) {
 		"Team registered",
 		"Your team has been named and you may begin using your team ID!",
 	)
+	ctx.LogEvent("register", req.FormValue("pid"), teamId, "", 0)
 }
 
 func (ctx *Instance) answerHandler(w http.ResponseWriter, req *http.Request) {
@@ -152,6 +153,7 @@ func (ctx *Instance) answerHandler(w http.ResponseWriter, req *http.Request) {
 			"Wrong answer",
 			"That is not the correct answer for %s %d.", category, points,
 		)
+		ctx.LogEvent("wrong", req.FormValue("pid"), teamId, category, points)
 		return
 	}
 
@@ -168,6 +170,7 @@ func (ctx *Instance) answerHandler(w http.ResponseWriter, req *http.Request) {
 		"Points awarded",
 		fmt.Sprintf("%d points for %s!", points, teamId),
 	)
+	ctx.LogEvent("correct", req.FormValue("pid"), teamId, category, points)
 }
 
 func (ctx *Instance) puzzlesHandler(w http.ResponseWriter, req *http.Request) {
@@ -342,7 +345,7 @@ func (ctx *Instance) ServeHTTP(wOrig http.ResponseWriter, r *http.Request) {
 
 	clientIP := r.RemoteAddr
 
-	if (ctx.UseXForwarded) {
+	if ctx.UseXForwarded {
 		forwardedIP := r.Header.Get("X-Forwarded-For")
 		forwardedIP = strings.Split(forwardedIP, ", ")[0]
 

src/instance.go

@@ -25,7 +25,7 @@ type Instance struct {
 	StateDir        string
 	ThemeDir        string
 	AttemptInterval time.Duration
-	UseXForwarded	bool
+	UseXForwarded   bool
 
 	Runtime RuntimeConfig
 
@@ -34,6 +34,8 @@ type Instance struct {
 	update            chan bool
 	jPuzzleList       []byte
 	jPointsLog        []byte
+	eventStream       chan string
+	eventLogWriter    io.WriteCloser
 	nextAttempt       map[string]time.Time
 	nextAttemptMutex  *sync.RWMutex
 	mux               *http.ServeMux
@@ -47,10 +49,17 @@ func (ctx *Instance) Initialize() error {
 	if _, err := os.Stat(ctx.StateDir); err != nil {
 		return err
 	}
+	if f, err := os.OpenFile(ctx.StatePath("events.log"), os.O_RDWR|os.O_CREATE, 0644); err != nil {
+		return err
+	} else {
+		// This stays open for the life of the process
+		ctx.eventLogWriter = f
+	}
 
 	ctx.Base = strings.TrimRight(ctx.Base, "/")
 	ctx.categories = map[string]*Mothball{}
 	ctx.update = make(chan bool, 10)
+	ctx.eventStream = make(chan string, 80)
 	ctx.nextAttempt = map[string]time.Time{}
 	ctx.nextAttemptMutex = new(sync.RWMutex)
 	ctx.mux = http.NewServeMux()
@@ -84,6 +93,7 @@ func (ctx *Instance) MaybeInitialize() {
 	os.Remove(ctx.StatePath("until"))
 	os.Remove(ctx.StatePath("disabled"))
 	os.Remove(ctx.StatePath("points.log"))
+	os.Remove(ctx.StatePath("events.log"))
 
 	os.RemoveAll(ctx.StatePath("points.tmp"))
 	os.RemoveAll(ctx.StatePath("points.new"))
@@ -102,6 +112,9 @@ func (ctx *Instance) MaybeInitialize() {
 		}
 	}
 
+	// Record that we did all this
+	ctx.LogEvent("init", "", "", "", 0)
+
 	// Create initialized file that signals whether we're set up
 	f, err := os.OpenFile(ctx.StatePath("initialized"), os.O_WRONLY|os.O_CREATE|os.O_EXCL, 0644)
 	if err != nil {
@@ -111,6 +124,30 @@ func (ctx *Instance) MaybeInitialize() {
 	fmt.Fprintln(f, "Remove this file to reinitialize the contest")
 }
 
+func logstr(s string) string {
+	if s == "" {
+		return "-"
+	}
+	return s
+}
+
+// LogEvent writes to the event log
+func (ctx *Instance) 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, " ", "-")
+	}
+	ctx.eventStream <- msg
+}
 func pathCleanse(parts []string) string {
 	clean := make([]string, len(parts))
 	for i := range parts {
@@ -155,7 +192,7 @@ func (ctx *Instance) TooFast(teamId string) bool {
 
 func (ctx *Instance) PointsLog(teamId string) AwardList {
 	awardlist := AwardList{}
-	
+
 	fn := ctx.StatePath("points.log")
 
 	f, err := os.Open(fn)

src/maintenance.go

@@ -204,15 +204,15 @@ func (ctx *Instance) readTeams() {
 // collectPoints gathers up files in points.new/ and appends their contents to points.log,
 // removing each points.new/ file as it goes.
 func (ctx *Instance) collectPoints() {
-  points := ctx.PointsLog("")
+	points := ctx.PointsLog("")
 
-  pointsFilename := ctx.StatePath("points.log")
+	pointsFilename := ctx.StatePath("points.log")
-  pointsNewFilename := ctx.StatePath("points.log.new")
+	pointsNewFilename := ctx.StatePath("points.log.new")
-  
+
-  // Yo, this is delicate.
+	// Yo, this is delicate.
-  // If we have to return early, we must remove this file.
+	// If we have to return early, we must remove this file.
-  // If the file's written and we move it successfully,
+	// If the file's written and we move it successfully,
-  // we need to remove all the little points files that built it.
+	// we need to remove all the little points files that built it.
 	newPoints, err := os.OpenFile(pointsNewFilename, os.O_CREATE|os.O_WRONLY|os.O_EXCL, 0644)
 	if err != nil {
 		log.Printf("Can't append to points log: %s", err)
@@ -248,7 +248,7 @@ func (ctx *Instance) collectPoints() {
 		if duplicate {
 			log.Printf("Skipping duplicate points: %s", award.String())
 		} else {
-		  points = append(points, award)
+			points = append(points, award)
 		}
 		removearino = append(removearino, filename)
 	}
@@ -257,21 +257,21 @@ func (ctx *Instance) collectPoints() {
 	for _, point := range points {
 		fmt.Fprintln(newPoints, point.String())
 	}
-	
+
 	newPoints.Close()
-	
+
 	if err := os.Rename(pointsNewFilename, pointsFilename); err != nil {
-	  log.Printf("Unable to move %s to %s: %s", pointsFilename, pointsNewFilename, err)
+		log.Printf("Unable to move %s to %s: %s", pointsFilename, pointsNewFilename, err)
-	  if err := os.Remove(pointsNewFilename); err != nil {
+		if err := os.Remove(pointsNewFilename); err != nil {
-	    log.Printf("Also couldn't remove %s: %s", pointsNewFilename, err)
+			log.Printf("Also couldn't remove %s: %s", pointsNewFilename, err)
-	  }
+		}
-	  return
+		return
 	}
 
 	for _, filename := range removearino {
-  	if err := os.Remove(filename); err != nil {
+		if err := os.Remove(filename); err != nil {
-  		log.Printf("Unable to remove %s: %s", filename, err)
+			log.Printf("Unable to remove %s: %s", filename, err)
-  	}
+		}
 	}
 }
 
@@ -322,10 +322,14 @@ func (ctx *Instance) Maintenance(maintenanceInterval time.Duration) {
 			ctx.collectPoints()
 			ctx.generatePuzzleList()
 			ctx.generatePointsLog("")
+		} else {
+			ctx.LogEvent("disabled", "", "", "", 0)
 		}
 		select {
 		case <-ctx.update:
 			// log.Print("Forced update")
+		case msg := <-ctx.eventStream:
+			fmt.Fprintln(ctx.eventLogWriter, msg)
 		case <-time.After(maintenanceInterval):
 			// log.Print("Housekeeping...")
 		}

src/mothd.go

@@ -73,6 +73,7 @@ func main() {
 	if err != nil {
 		log.Fatal(err)
 	}
+	defer ctx.eventLogWriter.Close()
 
 	// Add some MIME extensions
 	// Doing this avoids decompressing a mothball entry twice per request