diff --git a/CHANGELOG.md b/CHANGELOG.md index 0be1526..3520199 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/docs/logs.md b/docs/logs.md new file mode 100644 index 0000000..bfca2de --- /dev/null +++ b/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. diff --git a/src/handlers.go b/src/handlers.go index 7b2d6d2..9fbae14 100644 --- a/src/handlers.go +++ b/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] diff --git a/src/instance.go b/src/instance.go index 4c5c876..007d32c 100644 --- a/src/instance.go +++ b/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) diff --git a/src/maintenance.go b/src/maintenance.go index 829c2fc..47dcda3 100644 --- a/src/maintenance.go +++ b/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") - pointsNewFilename := ctx.StatePath("points.log.new") - - // Yo, this is delicate. - // If we have to return early, we must remove this file. - // If the file's written and we move it successfully, - // we need to remove all the little points files that built it. + pointsFilename := ctx.StatePath("points.log") + pointsNewFilename := ctx.StatePath("points.log.new") + + // Yo, this is delicate. + // If we have to return early, we must remove this file. + // If the file's written and we move it successfully, + // 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) - if err := os.Remove(pointsNewFilename); err != nil { - log.Printf("Also couldn't remove %s: %s", pointsNewFilename, err) - } - return + log.Printf("Unable to move %s to %s: %s", pointsFilename, pointsNewFilename, err) + if err := os.Remove(pointsNewFilename); err != nil { + log.Printf("Also couldn't remove %s: %s", pointsNewFilename, err) + } + return } for _, filename := range removearino { - if err := os.Remove(filename); err != nil { - log.Printf("Unable to remove %s: %s", filename, err) - } + if err := os.Remove(filename); err != nil { + 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...") } diff --git a/src/mothd.go b/src/mothd.go index a61666e..36d033b 100644 --- a/src/mothd.go +++ b/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