Cache state

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.
 

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]}}` {

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")

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")
+	s.lock.RLock()
-	teamNameBytes, err := afero.ReadFile(teamFs, teamID)
+	name, ok := s.teamNames[teamID]
-	if os.IsNotExist(err) {
+	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)
 	}
-
+	return name, nil
-	teamName := strings.TrimSpace(string(teamNameBytes))
-	return teamName, 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")
+	s.lock.RLock()
-	if err != nil {
+	ret := make(award.List, len(s.pointsLog))
-		log.Println(err)
+	copy(ret, s.pointsLog)
-		return nil
+	s.lock.RUnlock()
-	}
+	return ret
-	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
 }
 
 // Messages retrieves the current messages.
 func (s *State) Messages() string {
-	bMessages, _ := afero.ReadFile(s, "messages.html")
+	s.lock.RLock() // It's not clear to me that this actually needs to happen
-	return string(bMessages)
+	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.

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()
+	s.refresh()
-	if len(pl) != 1 {
+	if len(s.PointsLog()) != 2 {
-		t.Errorf("After awarding points, points log has length %d", len(pl))
+		t.Errorf("There should be two awards")
-	} else if (pl[0].TeamID != teamID) || (pl[0].Category != category) || (pl[0].Points != points) {
-		t.Errorf("Incorrect logged award %v", pl)
 	}
 
 	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")
 	}