diff --git a/CHANGELOG.md b/CHANGELOG.md index 21ba822..6173708 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,12 @@ 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). -## [unreleased] - 2021-10-20 +## [unreleased] - 2021-10-26 +### Added +- State is now cached in memory, in an attempt to reduce filesystem metadata operations, + which kill NFS. + +## [v4.4.5] - 2021-10-26 ### Added - Images deploying to docker hub too. We're now at capacity for our Docker Hub team. diff --git a/cmd/mothd/httpd_test.go b/cmd/mothd/httpd_test.go index 6c623c3..fc4ae9a 100644 --- a/cmd/mothd/httpd_test.go +++ b/cmd/mothd/httpd_test.go @@ -70,6 +70,8 @@ func TestHttpd(t *testing.T) { t.Error("Register failed", r.Body.String()) } + time.Sleep(TestMaintenanceInterval) + if r := hs.TestRequest("/state", nil); r.Result().StatusCode != 200 { t.Error(r.Result()) } else if r.Body.String() != `{"Config":{"Devel":false},"Messages":"messages.html","TeamNames":{"self":"GoTeam"},"PointsLog":[],"Puzzles":{"pategory":[1]}}` { diff --git a/cmd/mothd/server_test.go b/cmd/mothd/server_test.go index 2434e22..6b6e621 100644 --- a/cmd/mothd/server_test.go +++ b/cmd/mothd/server_test.go @@ -80,13 +80,16 @@ func TestProdServer(t *testing.T) { t.Error("index.html wrong contents", contents) } + // Wait for refresh to pick everything up + time.Sleep(TestMaintenanceInterval) + { es := handler.ExportState() if es.Config.Devel { t.Error("Marked as development server", es.Config) } if len(es.Puzzles) != 1 { - t.Error("Puzzle categories wrong length") + t.Error("Puzzle categories wrong length", len(es.Puzzles)) } if es.Messages != "messages.html" { t.Error("Messages has wrong contents") diff --git a/cmd/mothd/state.go b/cmd/mothd/state.go index b8cb231..9d11621 100644 --- a/cmd/mothd/state.go +++ b/cmd/mothd/state.go @@ -11,6 +11,7 @@ import ( "path/filepath" "strconv" "strings" + "sync" "time" "github.com/dirtbags/moth/pkg/award" @@ -42,6 +43,12 @@ type State struct { eventStream chan []string eventWriter *csv.Writer eventWriterFile afero.File + + // Caches, so we're not hammering NFS with metadata operations + teamNames map[string]string + pointsLog award.List + messages string + lock sync.RWMutex } // NewState returns a new State struct backed by the given Fs @@ -51,6 +58,8 @@ func NewState(fs afero.Fs) *State { Enabled: true, refreshNow: make(chan bool, 5), eventStream: make(chan []string, 80), + + teamNames: make(map[string]string), } if err := s.reopenEventLog(); err != nil { log.Fatal(err) @@ -120,16 +129,13 @@ func (s *State) updateEnabled() { // TeamName returns team name given a team ID. func (s *State) TeamName(teamID string) (string, error) { - teamFs := afero.NewBasePathFs(s.Fs, "teams") - teamNameBytes, err := afero.ReadFile(teamFs, teamID) - if os.IsNotExist(err) { + s.lock.RLock() + name, ok := s.teamNames[teamID] + s.lock.RUnlock() + if !ok { return "", fmt.Errorf("unregistered team ID: %s", teamID) - } else if err != nil { - return "", fmt.Errorf("unregistered team ID: %s (%s)", teamID, err) } - - teamName := strings.TrimSpace(string(teamNameBytes)) - return teamName, nil + return name, nil } // SetTeamName writes out team name. @@ -163,36 +169,26 @@ func (s *State) SetTeamName(teamID, teamName string) error { log.Printf("Setting team name [%s] in file %s", teamName, teamFilename) fmt.Fprintln(teamFile, teamName) teamFile.Close() + + s.refreshNow <- true + return nil } // PointsLog retrieves the current points log. func (s *State) PointsLog() award.List { - f, err := s.Open("points.log") - if err != nil { - log.Println(err) - return nil - } - defer f.Close() - - pointsLog := make(award.List, 0, 200) - scanner := bufio.NewScanner(f) - for scanner.Scan() { - line := scanner.Text() - cur, err := award.Parse(line) - if err != nil { - log.Printf("Skipping malformed award line %s: %s", line, err) - continue - } - pointsLog = append(pointsLog, cur) - } - return pointsLog + s.lock.RLock() + ret := make(award.List, len(s.pointsLog)) + copy(ret, s.pointsLog) + s.lock.RUnlock() + return ret } // Messages retrieves the current messages. func (s *State) Messages() string { - bMessages, _ := afero.ReadFile(s, "messages.html") - return string(bMessages) + s.lock.RLock() // It's not clear to me that this actually needs to happen + defer s.lock.RUnlock() + return s.messages } // AwardPoints gives points to teamID in category. @@ -260,12 +256,14 @@ func (s *State) collectPoints() { } duplicate := false - for _, e := range s.PointsLog() { + s.lock.RLock() + for _, e := range s.pointsLog { if awd.Equal(e) { duplicate = true break } } + s.lock.RUnlock() if duplicate { log.Print("Skipping duplicate points: ", awd.String()) @@ -279,6 +277,11 @@ func (s *State) collectPoints() { } fmt.Fprintln(logf, awd.String()) logf.Close() + + // Stick this on the cache too + s.lock.Lock() + s.pointsLog = append(s.pointsLog, awd) + s.lock.Unlock() } if err := s.Remove(filename); err != nil { @@ -402,12 +405,64 @@ func (s *State) reopenEventLog() error { return nil } +func (s *State) updateCaches() { + s.lock.Lock() + defer s.lock.Unlock() + + if f, err := s.Open("points.log"); err != nil { + log.Println(err) + } else { + defer f.Close() + + pointsLog := make(award.List, 0, 200) + scanner := bufio.NewScanner(f) + for scanner.Scan() { + line := scanner.Text() + cur, err := award.Parse(line) + if err != nil { + log.Printf("Skipping malformed award line %s: %s", line, err) + continue + } + pointsLog = append(pointsLog, cur) + } + s.pointsLog = pointsLog + } + + { + // The compiler recognizes this as an optimization case + for k := range s.teamNames { + delete(s.teamNames, k) + } + + teamsFs := afero.NewBasePathFs(s.Fs, "teams") + if dirents, err := afero.ReadDir(teamsFs, "."); err != nil { + log.Printf("Reading team ids: %v", err) + } else { + for _, dirent := range dirents { + teamID := dirent.Name() + if teamNameBytes, err := afero.ReadFile(teamsFs, teamID); err != nil { + log.Printf("Reading team %s: %v", teamID, err) + } else { + teamName := strings.TrimSpace(string(teamNameBytes)) + s.teamNames[teamID] = teamName + } + } + } + + } + + if bMessages, err := afero.ReadFile(s, "messages.html"); err == nil { + s.messages = string(bMessages) + } +} + func (s *State) refresh() { s.maybeInitialize() s.updateEnabled() if s.Enabled { s.collectPoints() } + s.updateCaches() } // Maintain performs housekeeping on a State struct. diff --git a/cmd/mothd/state_test.go b/cmd/mothd/state_test.go index 5cb1097..21f1ea2 100644 --- a/cmd/mothd/state_test.go +++ b/cmd/mothd/state_test.go @@ -62,6 +62,7 @@ func TestState(t *testing.T) { if err := s.SetTeamName(teamID, "wat"); err == nil { t.Errorf("Registering team a second time didn't fail") } + s.refresh() if name, err := s.TeamName(teamID); err != nil { t.Error(err) } else if name != teamName { @@ -73,9 +74,6 @@ func TestState(t *testing.T) { if err := s.AwardPoints(teamID, category, points); err != nil { t.Error(err) } - if err := s.AwardPoints(teamID, category, points); err != nil { - t.Error("Two awards before refresh:", err) - } // Flex duplicate detection with different timestamp if f, err := s.Create("points.new/moo"); err != nil { t.Error("Creating duplicate points file:", err) @@ -83,24 +81,34 @@ func TestState(t *testing.T) { fmt.Fprintln(f, time.Now().Unix()+1, teamID, category, points) f.Close() } + + s.AwardPoints(teamID, category, points) s.refresh() + pl = s.PointsLog() + if len(pl) != 1 { + for i, award := range pl { + t.Logf("pl[%d] == %s", i, award.String()) + } + t.Errorf("After awarding duplicate points, points log has length %d", len(pl)) + } else if (pl[0].TeamID != teamID) || (pl[0].Category != category) || (pl[0].Points != points) { + t.Errorf("Incorrect logged award %v", pl) + } if err := s.AwardPoints(teamID, category, points); err == nil { - t.Error("Duplicate points award didn't fail") + t.Error("Duplicate points award after refresh didn't fail") } if err := s.AwardPoints(teamID, category, points+1); err != nil { t.Error("Awarding more points:", err) } - pl = s.PointsLog() - if len(pl) != 1 { - t.Errorf("After awarding points, points log has length %d", len(pl)) - } else if (pl[0].TeamID != teamID) || (pl[0].Category != category) || (pl[0].Points != points) { - t.Errorf("Incorrect logged award %v", pl) + s.refresh() + if len(s.PointsLog()) != 2 { + t.Errorf("There should be two awards") } afero.WriteFile(s, "points.log", []byte("intentional parse error\n"), 0644) + s.refresh() if len(s.PointsLog()) != 0 { t.Errorf("Intentional parse error breaks pointslog") } @@ -108,7 +116,8 @@ func TestState(t *testing.T) { t.Error(err) } s.refresh() - if len(s.PointsLog()) != 2 { + if len(s.PointsLog()) != 1 { + t.Log(s.PointsLog()) t.Error("Intentional parse error screws up all parsing") }