Add player tracking and shutdown to supertuxkart example (googleforga…

…mes#1825)

Signed-off-by: Andrew Suderman <[email protected]>

examples/supertuxkart/Dockerfile

@@ -62,5 +62,6 @@ COPY server_config.xml .
 
 RUN chown -R supertuxkart:supertuxkart /home/supertuxkart && chmod +x wrapper
 
+ENV ENABLE_PLAYER_TRACKING=false
 USER 1000
 ENTRYPOINT ["./entrypoint.sh"]

examples/supertuxkart/Makefile

@@ -27,7 +27,7 @@ REPOSITORY = gcr.io/agones-images
 
 mkfile_path := $(abspath $(lastword $(MAKEFILE_LIST)))
 project_path := $(dir $(mkfile_path))
-image_tag = $(REPOSITORY)/supertuxkart-example:0.2
+image_tag = $(REPOSITORY)/supertuxkart-example:0.3
 
 #   _____                    _
 #  |_   _|_ _ _ __ __ _  ___| |_ ___
@@ -40,6 +40,10 @@ image_tag = $(REPOSITORY)/supertuxkart-example:0.2
 build:
 	docker build -f $(project_path)/Dockerfile --tag=$(image_tag) .
 
+# Run tests
+test:
+	go test -v ./...
+
 # check if hosted on Google Cloud Registry
 gcr-check:
 	gcloud container images describe $(image_tag)

examples/supertuxkart/entrypoint.sh

@@ -17,4 +17,4 @@
 set -e
 set +x
 
-./wrapper -i "./cmake_build/bin/supertuxkart --server-config=$(pwd)/server_config.xml"
+./wrapper -i "./cmake_build/bin/supertuxkart --server-config=$(pwd)/server_config.xml" -player-tracking="$ENABLE_PLAYER_TRACKING"

examples/supertuxkart/gameserver.yaml

@@ -26,3 +26,6 @@ spec:
       - name: supertuxkart
         image: gcr.io/agones-images/supertuxkart-example:0.2
         # imagePullPolicy: Always # add for development
+        env:
+          - name: ENABLE_PLAYER_TRACKING
+            value: 'false'

examples/supertuxkart/go.mod

@@ -2,4 +2,8 @@ module supertuxkart
 
 go 1.13
 
-require agones.dev/agones v1.4.0
+require (
+	agones.dev/agones v1.8.0
+	github.com/hpcloud/tail v1.0.0
+	github.com/stretchr/testify v1.5.0
+)

examples/supertuxkart/main.go

@@ -17,15 +17,16 @@ package main
 import (
 	"flag"
 	"fmt"
-	"io/ioutil"
 	"log"
 	"os"
 	"os/exec"
 	"path"
+	"regexp"
 	"strings"
 	"time"
 
 	sdk "agones.dev/agones/sdks/go"
+	"github.com/hpcloud/tail"
 )
 
 // logLocation is the path to the location of the SuperTuxKart log file
@@ -34,20 +35,31 @@ const logLocation = "/.config/supertuxkart/config-0.10/server_config.log"
 // main intercepts the log file of the SuperTuxKart gameserver and uses it
 // to determine if the game server is ready or not.
 func main() {
+	log.SetPrefix("[wrapper] ")
 	input := flag.String("i", "", "the command and arguments to execute the server binary")
+
+	// Since player tracking is not on by default, it is behind this flag.
+	// If it is off, still log messages about players, but don't actually call the player tracking functions.
+	enablePlayerTracking := flag.Bool("player-tracking", false, "If true, player tracking will be enabled.")
 	flag.Parse()
 
-	fmt.Println(">>> Connecting to Agones with the SDK")
+	log.Println("Connecting to Agones with the SDK")
 	s, err := sdk.NewSDK()
 	if err != nil {
-		log.Fatalf(">>> Could not connect to SDK: %v", err)
+		log.Fatalf("could not connect to SDK: %v", err)
+	}
+
+	if *enablePlayerTracking {
+		if err = s.Alpha().SetPlayerCapacity(8); err != nil {
+			log.Fatalf("could not set play count: %v", err)
+		}
 	}
 
-	fmt.Println(">>> Starting health checking")
+	log.Println("Starting health checking")
 	go doHealth(s)
 
-	fmt.Println(">>> Starting wrapper for SuperTuxKart")
-	fmt.Printf(">>> Command being run for SuperTuxKart server: %s \n", *input)
+	log.Println("Starting wrapper for SuperTuxKart")
+	log.Printf("Command being run for SuperTuxKart server: %s \n", *input)
 
 	cmdString := strings.Split(*input, " ")
 	command, args := cmdString[0], cmdString[1:]
@@ -57,58 +69,120 @@ func main() {
 	cmd.Stdout = os.Stdout
 
 	if err := cmd.Start(); err != nil {
-		log.Fatalf(">>> Error starting cmd: %v", err)
+		log.Fatalf("error starting cmd: %v", err)
 	}
 
 	// SuperTuxKart refuses to output to foreground, so we're going to
 	// poll the server log.
-	ready := false
 	home, err := os.UserHomeDir()
 	if err != nil {
-		log.Fatalf(">>> Could not get home dir: %v", err)
+		log.Fatalf("could not get home dir: %v", err)
 	}
-	for i := 0; i <= 10; i++ {
-		time.Sleep(time.Second)
 
-		logFile, err := os.Open(path.Join(home, logLocation))
-		if err != nil {
-			log.Printf(">>> Could not open server log: %v", err)
-			continue
-		}
+	t := &tail.Tail{}
+	// Loop to make sure the log has been created. Sometimes it takes a few seconds
+	for i := 0; i < 10; i++ {
+		time.Sleep(time.Second)
 
-		content, err := ioutil.ReadAll(logFile)
+		t, err = tail.TailFile(path.Join(home, logLocation), tail.Config{Follow: true})
 		if err != nil {
-			log.Printf(">>> Could not read server file: %v", err)
+			log.Print(err)
 			continue
+		} else {
+			break
 		}
-		output := string(content)
-		println(">>> Output from server_config.log:")
-		print(output)
-
-		if strings.Contains(output, "Listening has been started") {
-			ready = true
-			log.Printf(">>> Moving to READY!")
+	}
+	defer t.Cleanup()
+	for line := range t.Lines {
+		// Don't use the logger here. This would add multiple prefixes to the logs. We just want
+		// to show the supertuxkart logs as they are, and layer the wrapper logs in with them.
+		fmt.Println(line.Text)
+		action, player := handleLogLine(line.Text)
+		switch action {
+		case "READY":
 			if err := s.Ready(); err != nil {
-				log.Fatalf(">>> Could not send ready message")
+				log.Fatal("failed to mark server ready")
 			}
-			break
+		case "PLAYERJOIN":
+			if player == nil {
+				log.Print("could not determine player")
+				break
+			}
+			if *enablePlayerTracking {
+				result, err := s.Alpha().PlayerConnect(*player)
+				if err != nil {
+					log.Print(err)
+				} else {
+					log.Print(result)
+				}
+			}
+		case "PLAYERLEAVE":
+			if player == nil {
+				log.Print("could not determine player")
+				break
+			}
+			if *enablePlayerTracking {
+				result, err := s.Alpha().PlayerDisconnect(*player)
+				if err != nil {
+					log.Print(err)
+				} else {
+					log.Print(result)
+				}
+			}
+		case "SHUTDOWN":
+			if err := s.Shutdown(); err != nil {
+				log.Fatal(err)
+			}
+			os.Exit(0)
 		}
 	}
-	if ready == false {
-		log.Fatalf(">>> Server did not become ready within 10 seconds")
-	}
-
-	err = cmd.Wait()
-	log.Fatalf(">>> SuperTuxKart shutdown unexpectedly: %v", err)
+	log.Fatal("tail ended")
 }
 
 // doHealth sends the regular Health Pings
 func doHealth(sdk *sdk.SDK) {
 	tick := time.Tick(2 * time.Second)
 	for {
 		if err := sdk.Health(); err != nil {
-			log.Fatalf(">>> Could not send health ping: %v", err)
+			log.Fatalf("could not send health ping: %v", err)
 		}
 		<-tick
 	}
 }
+
+// handleLogLine compares the log line to a series of regexes to determine if any action should be taken.
+// TODO: This could probably be handled better with a custom type rather than just (string, *string)
+func handleLogLine(line string) (string, *string) {
+	// The various regexes that match server lines
+	playerJoin := regexp.MustCompile(`ServerLobby: New player (.+) with online id [0-9][0-9]?`)
+	playerLeave := regexp.MustCompile(`ServerLobby: (.+) disconnected$`)
+	noMorePlayers := regexp.MustCompile(`STKHost.+There are now 0 peers\.$`)
+	serverStart := regexp.MustCompile(`Listening has been started`)
+
+	// Start the server
+	if serverStart.MatchString(line) {
+		log.Print("server ready")
+		return "READY", nil
+	}
+
+	// Player tracking
+	if playerJoin.MatchString(line) {
+		matches := playerJoin.FindSubmatch([]byte(line))
+		player := string(matches[1])
+		log.Printf("Player %s joined\n", player)
+		return "PLAYERJOIN", &player
+	}
+	if playerLeave.MatchString(line) {
+		matches := playerLeave.FindSubmatch([]byte(line))
+		player := string(matches[1])
+		log.Printf("Player %s disconnected", player)
+		return "PLAYERLEAVE", &player
+	}
+
+	// All the players left, send a shutdown
+	if noMorePlayers.MatchString(line) {
+		log.Print("server has no more players. shutting down")
+		return "SHUTDOWN", nil
+	}
+	return "", nil
+}

examples/supertuxkart/main_test.go

@@ -0,0 +1,70 @@
+// Copyright 2020 Google LLC All Rights Reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package main
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func Test_handleLogLine(t *testing.T) {
+	tests := []struct {
+		name   string
+		line   string
+		want   string
+		player string
+	}{
+		{
+			name:   "start",
+			line:   `Fri Sep 18 16:22:11 2020 [info   ] STKHost: Listening has been started.`,
+			want:   "READY",
+			player: "",
+		},
+		{
+			name:   "player join",
+			line:   `Fri Sep 18 01:54:59 2020 [info   ] ServerLobby: New player sudermanjr with online id 0 from 64.40.3.124:15009 with SuperTuxKart/1.1 (Macintosh).`,
+			want:   "PLAYERJOIN",
+			player: "sudermanjr",
+		},
+		{
+			name:   "player leave",
+			line:   `Thu Sep 17 23:27:57 2020 [info   ] ServerLobby: sudermanjr disconnected`,
+			want:   "PLAYERLEAVE",
+			player: "sudermanjr",
+		},
+		{
+			name:   "shutdown",
+			line:   `Thu Sep 17 23:27:57 2020 [info   ] STKHost: 64.40.3.124:52325 has just disconnected. There are now 0 peers.`,
+			want:   "SHUTDOWN",
+			player: "",
+		},
+		{
+			name:   "other",
+			line:   `Thu Sep 17 23:23:07 2020 [info   ] ServerLobby: Message of type 17 received.`,
+			want:   "",
+			player: "",
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			got, player := handleLogLine(tt.line)
+			assert.EqualValues(t, tt.want, got)
+			if player != nil {
+				assert.Equal(t, tt.player, *player)
+			}
+		})
+	}
+}